Terraform hangs on plan/apply

Having an issue with Terraform hanging on apply or plan. Setting TF_LOG=1 doesn't seem to reveal any useful information, and running strace isn't overly helpful as well.

Will attach my debug log.

Debug log at: http://pastebitch.com/TOMO

I've tried this with GOMAXPROCS set to 16, and unset.

I've only recently fiddled with GOMAXPROCS (approximately the same time as this issue started) because I'm running a local Consul cluster for testing terraform -> Consul.

I'm having the same problem since yesterday:

https://gist.github.com/ryanking/94986ce2450984d77358

When it stalls there are typically a number of processes running:

ryanking        13346   0.3  0.1 145171076   5208 s000  S+   10:32AM   0:00.02 /Users/ryanking/bin/terraform-provisioner-remote-exec
ryanking        13347   0.3  0.1 145171092   5192 s000  S+   10:32AM   0:00.02 /Users/ryanking/bin/terraform-provisioner-file
ryanking        13345   0.2  0.1 145169868   4800 s000  S+   10:32AM   0:00.02 /Users/ryanking/bin/terraform-provisioner-local-exec
ryanking        13348   0.2  0.1 145171112   5312 s000  S+   10:32AM   0:00.03 /Users/ryanking/bin/terraform-provisioner-chef
ryanking        13350   0.0  0.1 145181524   9936 s000  S+   10:32AM   0:00.09 /Users/ryanking/bin/terraform-provider-aws
ryanking        13349   0.0  0.1 145170208   4792 s000  S+   10:32AM   0:00.03 /Users/ryanking/bin/terraform-provider-cloudflare
ryanking        13342   0.0  0.4 145174588  31296 s000  S+   10:32AM   0:00.81 /Users/ryanking/bin/terraform plan
ryanking        13341   0.0  0.1 145174332   5256 s000  S+   10:32AM   0:00.19 terraform plan

Running dtruss on them reveals a lot of select looping:

...
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
gettimeofday(0x208C5CED0, 0x0, 0x0)      = 1438190792 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x208C55F38)      = 0 0
...

I first had the problem on 0.6.0 yesterday. Upgrading to 0.6.1 didn't help. I tried older versions of my terraform configs and those also hung.

A colleague did a run on 0.5.3 and saw the same problem.

I've tried setting GOMAXPROCS to a ridiculously high number and that didn't help.

This is definitely odd. I'm suspicious of the "close" nodes I'm seeing towards the bottom of both of your debug logs...

From the 0.6.0 changelog:

core: Properly close provider and provisioner plugin connections [GH-2406, GH-2527]

I know one of you had a coworker try v0.5.3... can you both double check with v0.5.3?

Here is my coworker running the same configs with 0.5.3:

https://gist.github.com/anonymous/e27884ec1d834ae16b33

it stalls too

Debug log for 0.5.3: http://pastebitch.com/CATC

I did have to change the catalog a bit to get around some 0.5.x bugs with providers, so it's not identical, but it still stalls.

Running it under strace with just network tracing on shows Terraform trying to connect to a 169.254.169.254 address, I wonder if it has something to do an AWS provider?

http://pastebitch.com/eZAJ

@LeftyBC

@LeftyBC Interesting that you have several processes trying to connect there.

Perhaps this timeout is not working:

terraform/builtin/providers/aws/provider.go

Line 39 in c721738

conn, err := net.DialTimeout("tcp", "169.254.169.254:80", 100*time.Millisecond)

These are good theories. Trying to do a bit of differential diagnosis here.

The metadata service 169.254.169.254 authentication mechanism was added between v0.6.0 and v0.6.1 da1cac6

The close provider feature was added between v0.5.3 and v0.6.0.

So the fact that it stalls for both of you on 0.5.3 as well seems to discredit those theories.

Does any binary searching through your configs by commenting out portions seem to affect the reproduction of the hanging?

Similarly, do any runs from your commit history avoid the hang? Hopefully with more data like this we can narrow down the issue.

I'll go back through the commit log and see if I can get it to not hang, stand by.

Going back several versions in my commit log doesn't seem to help, even commits that I know were working a week ago, etc. Trying with 0.5.3 and 0.6.2 each time I go back a commit still gives me the hang.

Debug log for 0.6.1 with GOMAXPROCS=254 on a commit that I know should work: http://pastebitch.com/DAfA

Here's the strace output for the run that generated the above debug log - I killed it just after the normal hang: http://pastebitch.com/eFbg

@ryanking

I think so. I also changed the name of the resource that was referring to the module after I moved it to the environment submodule.

In the root, it was

module "cts_vpc" {
    source = "modules/components/cts_vpc"
...
}

It was then moved to the environment submodule in modules/environments/opsdev:

module "cts_vpc" {
   source = "../../components/cts_vpc"
...
}

I then changed it to:

module "cts_nonprod_vpc" {
  source = "../../components/cts_vpc"
...
}

I believe this is what left a bunch of "empty" modules in the state, as @ryanking saw.

core: fix deadlock when dependable node replaced with non-dependable one

Hey folks - this should be fixed in Terraform 0.6.3. Let me know if you still have any troubles on that version!

I have this issue with 0.6.3 on Mac OSX Yosemite. In case it matters, it was installed via brew.

Running terraform plan on the first getting start guide example.tf causes a hang, with the following repeatedly output when TF_LOG=1

$ TF_LOG=1 terraform plan

...
2015/08/28 12:34:45 [DEBUG] vertex provider.aws (close), waiting for: aws_instance.example
2015/08/28 12:34:45 [DEBUG] vertex aws_instance.example, waiting for: provider.aws
2015/08/28 12:34:45 [DEBUG] vertex root, waiting for: provider.aws (close)

$ terraform show
No state.

UPDATE:
Actually, I've found I was just too impatient. The plan returned correct output after 20 minutes! So, still some sort of issue there. Terraform log here: http://pastebitch.com/MBfA

@typerlc

@typerlc weird! It's possible that could happen due to transient networking issues - is this something that happens every time for you? If so, can you open a fresh issue with the config that reproduces? Thanks!

@typerlc

@typerlc is it possible that you ran terraform plan without AWS credentials set, either in your config or in the environment?

The AWS provider has some special behavior to try to obtain instance role credentials as if it were running on an EC2 instance, which applies if it doesn't find any explicit credentials in the configuration. This involves reaching out to http://169.254.169.254/latest/meta-data/, which of course won't do the right thing if you're not actually running on an EC2 instance... it could do anything from time out trying to send packets into oblivion, to getting a "no route to host" error, to actually talking to a different machine in your local network that happens to have that IP address.

I've personally run into this a few times and it ends up looking a lot like a hang. I expect it could be addressed by setting a pretty aggressive timeout on that request, assuming that the metadata endpoint on EC2 should respond reasonably quickly if you're actually on an EC2 instance.

@phinze

@phinze I doubt its a networking issue. Happens from my office network, mobile phone network and home network. While doing this, I have also browsed the internet, accessed the AWS console, etc.
As requested, I've opened a new issue #3118 to track.

@apparentlymart My .tf file had my AWS credentials. I've included my config file in the new issue #3118.

For anyone hitting this issue against AWS, be sure to check the AWS Service Health Dashboard. For instance, currently IAM N. Virginia is reporting We are continuing to investigate increased error rates and latencies on IAM administrative APIs and Console. This can cause aws.iam.GetUser to take several minutes to complete (possibly retrying multiple times after getting a 503 response), making Terraform appear to hang at startup.

Same issue on latest version.

Navigation Menu

Repository navigation

Terraform hangs on plan/apply #2884

9 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Terraform hangs on plan/apply #2884

Description

Activity

LeftyBC commented on Jul 29, 2015

LeftyBC commented on Jul 29, 2015

ryanking commented on Jul 29, 2015

phinze commented on Jul 29, 2015

ryanking commented on Jul 29, 2015

LeftyBC commented on Jul 29, 2015

LeftyBC commented on Jul 29, 2015

ryanking commented on Jul 29, 2015

ryanking commented on Jul 29, 2015

phinze commented on Jul 29, 2015

phinze commented on Jul 29, 2015

LeftyBC commented on Jul 29, 2015

LeftyBC commented on Jul 29, 2015

9 remaining items

LeftyBC commented on Jul 29, 2015

phinze commented on Aug 13, 2015

typerlc commented on Aug 28, 2015

phinze commented on Aug 28, 2015

apparentlymart commented on Aug 28, 2015

typerlc commented on Aug 29, 2015

trevorr commented on Aug 22, 2016

iahmad-khan commented on Oct 31, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions