search

mitchellh / vagrant-aws

Use Vagrant to manage your EC2 and VPC instances.
MIT License
2.61k stars 572 forks source link

provisioning hangs indefinitely when there is no output from provisioner script #377

Open timurb opened 9 years ago

timurb commented 9 years ago

Hi,

When I use the following Vagrantfile the provisioning freezes when I use provider AWS (but works ok when I use provider Virtualbox):

 -*- mode: ruby -*-
# vi: set ft=ruby :

# Vagrantfile API/syntax version. Don't touch unless you know what you're doing!
VAGRANTFILE_API_VERSION = "2"

Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|

  # Config for Virtualbox provider
  config.vm.provider "virtualbox" do |_,override|
    override.vm.box = "hashicorp/precise64"
    override.vm.network "private_network", ip: "192.168.133.40"
  end

  # Config for AWS provider
  config.vm.provider "aws" do |aws,override|
    override.vm.box = "dummy"
    override.vm.box_url = "https://github.com/mitchellh/vagrant-aws/raw/master/dummy.box"
    override.ssh.private_key_path = "CHANGEME"
    override.ssh.username = "ubuntu"

    aws.access_key_id = ENV['AWS_ACCESS_KEY_ID']
    aws.secret_access_key = ENV['AWS_SECRET_ACCESS_KEY']

    aws.region = "us-west-2"
    aws.instance_type = "c3.large"
    aws.keypair_name = "CHANGEME"
    aws.ami = "ami-937959a3" # latest AMI for Ubuntu Precise
    aws.security_groups = "Testing" # Changeme
  end

  sleep = []
  7.times do |x|
    sleep << "echo -n '#{x}: '"
    sleep << "date"
    sleep << "sleep 600"
  end
  config.vm.provision 'shell', inline: sleep.join(';')
  config.ssh.forward_agent = true
end

If I set sleep interval as low as ~120 seconds I see 10 "echo" lines which I'd expect but when I set it large enough I see only the first "echo" line. I think I've seen that for as low as 300 seconds but I could not reproduce that. With 600 seconds reproduces reliably.

Here is the output of vagrant up --debug --provider=aws (stripped):

==> default: Running provisioner: shell...
 INFO environment: Running hook: provisioner_run
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 4 hooks defined.
 INFO runner: Running action: #<Method: Vagrant::Action::Builtin::Provision#run_provisioner>
 INFO warden: Calling IN action: #<Proc:0x00000100f8a650@/opt/vagrant/embedded/gems/gems/vagrant-1.7.2/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO machine: Calling action: read_ssh_info on provider AWS (i-77865a7a)
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 4 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x00000100feaa50>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100ff3380>
 INFO warden: Calling IN action: #<VagrantPlugins::AWS::Action::ConnectAWS:0x00000100ff3358>
 INFO connect_aws: Connecting to AWS...
 INFO warden: Calling IN action: #<VagrantPlugins::AWS::Action::ReadSSHInfo:0x000001050208e0>
 INFO warden: Calling OUT action: #<VagrantPlugins::AWS::Action::ReadSSHInfo:0x000001050208e0>
 INFO warden: Calling OUT action: #<VagrantPlugins::AWS::Action::ConnectAWS:0x00000100ff3358>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100ff3380>
DEBUG ssh: Checking key permissions: /private/tmp/testcase/engg-qa.pem
DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: chown -R ubuntu /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: stdin: is not a tty

DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: echo; printf $SSH_AUTH_SOCK (sudo=false)
DEBUG ssh: stdout:

DEBUG ssh: stdout: /tmp/ssh-sEiTibr981/agent.981
DEBUG ssh: Exit status: 0
 INFO ssh: Setting SSH_AUTH_SOCK remotely: /tmp/ssh-sEiTibr981/agent.981
DEBUG ssh: stderr: chown: cannot access `/tmp/vagrant-shell'
DEBUG ssh: stderr: : No such file or directory

DEBUG ssh: Exit status: 1
DEBUG ssh: Uploading: /var/folders/5j/z2j_7z957vg9t4sv218wjwjw0000gn/T/vagrant-shell20150322-15516-11a5oc4.ps1 to /tmp/vagrant-shell
DEBUG ssh: Re-using SSH connection.
 INFO interface: detail: Running: inline script
 INFO interface: detail:     default: Running: inline script
    default: Running: inline script
DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: chmod +x /tmp/vagrant-shell && /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: stdin: is not a tty

 INFO interface: info: stdin: is not a tty
 INFO interface: info: ==> default: stdin: is not a tty
==> default: stdin: is not a tty
DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: echo; printf $SSH_AUTH_SOCK (sudo=false)
DEBUG ssh: stdout:

DEBUG ssh: stdout: /tmp/ssh-sEiTibr981/agent.981
DEBUG ssh: Exit status: 0
 INFO ssh: Setting SSH_AUTH_SOCK remotely: /tmp/ssh-sEiTibr981/agent.981
DEBUG ssh: stdout: 0:
 INFO interface: info: 0:
 INFO interface: info: ==> default: 0:
==> default: 0:
DEBUG ssh: stdout: Sun Mar 22 17:25:57 UTC 2015

 INFO interface: info: Sun Mar 22 17:25:57 UTC 2015
 INFO interface: info: ==> default: Sun Mar 22 17:25:57 UTC 2015
==> default: Sun Mar 22 17:25:57 UTC 2015
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
..................

The DEBUG ssh: Sending SSH keep-alive... lines repeat indefinitely each 5 seconds but after 10 minutes I see no new "echo" lines. If I reduce the interval or select virtualbox provider I'll see the output like the following:

==> default: Running provisioner: shell...
    default: Running: inline script
==> default: stdin: is not a tty
==> default: 0:
==> default: Sun Mar 22 15:18:59 UTC 2015
==> default: 1:
==> default: Sun Mar 22 15:28:59 UTC 2015
==> default: 2:
==> default: Sun Mar 22 15:38:59 UTC 2015
==> default: 3:
==> default: Sun Mar 22 15:48:59 UTC 2015
==> default: 4:
==> default: Sun Mar 22 15:58:59 UTC 2015
==> default: 5:
==> default: Sun Mar 22 16:08:59 UTC 2015
==> default: 6:
==> default: Sun Mar 22 16:18:59 UTC 2015
==> default: Configuring cache buckets...
timurb commented 9 years ago 
timurb@macpro777:~$ vagrant --version
Vagrant 1.7.2
timurb@macpro777:~$ uname -a
Darwin macpro777 14.1.0 Darwin Kernel Version 14.1.0: Thu Feb 26 19:26:47 PST 2015; root:xnu-2782.10.73~1/RELEASE_X86_64 x86_64
timurb commented 9 years ago

While I see no signs of script working looking from my PC, on the server the script continues to run:

local PC:

==> default: Running provisioner: shell...
    default: Running: inline script
==> default: stdin: is not a tty
==> default: 0:
==> default: Sun Mar 22 17:50:15 UTC 2015

Remote server:

ubuntu     998   752  0 17:48 ?        00:00:00 sshd: ubuntu@notty
root      1298   998  0 17:50 ?        00:00:00 sudo -E -H bash -l
root      1299  1298  0 17:50 ?        00:00:00 bash -l
root      1308  1299  0 17:50 ?        00:00:00 bash -l
root      1311   615  0 17:50 ?        00:00:00 sshd: ubuntu [priv]
ubuntu    1425  1311  0 17:50 ?        00:00:00 sshd: ubuntu@pts/0
ubuntu    1426  1425  0 17:50 pts/0    00:00:00 -bash
root      1524  1426  0 17:50 pts/0    00:00:00 sudo -i
root      1525  1524  0 17:50 pts/0    00:00:00 -bash
root      1589  1308  0 18:00 ?        00:00:00 sleep 600

If I break the Vagrant run using Ctrl-C twice the script still continues working on the server:

ubuntu     998   752  0 17:48 ?        00:00:00 sshd: ubuntu@notty
root      1298   998  0 17:50 ?        00:00:00 sudo -E -H bash -l
root      1299  1298  0 17:50 ?        00:00:00 bash -l
root      1308  1299  0 17:50 ?        00:00:00 bash -l
root      1311   615  0 17:50 ?        00:00:00 sshd: ubuntu [priv]
ubuntu    1425  1311  0 17:50 ?        00:00:00 sshd: ubuntu@pts/0
ubuntu    1426  1425  0 17:50 pts/0    00:00:00 -bash
root      1524  1426  0 17:50 pts/0    00:00:00 sudo -i
root      1525  1524  0 17:50 pts/0    00:00:00 -bash
root      1595  1308  0 18:10 ?        00:00:00 sleep 600
timurb commented 9 years ago

At the moment I hit Ctrl-C the ssh session created by Vagrant is still seen from server side:

root      1283     1  0 19:41 ?        00:00:00 sudo -E -H bash -l
root      1284  1283  0 19:41 ?        00:00:00 bash -l
root      1293  1284  0 19:41 ?        00:00:00 bash -l
root      1296   597  0 19:44 ?        00:00:00 sshd: ubuntu [priv]
ubuntu    1410  1296  0 19:45 ?        00:00:00 sshd: ubuntu@pts/0
ubuntu    1411  1410  0 19:45 pts/0    00:00:00 -bash
root      1513  1293  0 20:01 ?        00:00:00 sleep 600
root      1514     2  0 20:08 ?        00:00:00 [flush-202:1]
root      1515   597  0 20:09 ?        00:00:00 sshd: ubuntu [priv]
ubuntu    1629  1515  0 20:09 ?        00:00:00 sshd: ubuntu@pts/1
ubuntu    1630  1629  2 20:09 pts/1    00:00:00 -bash
ubuntu    1728  1630  0 20:09 pts/1    00:00:00 ps -ef
ubuntu@ip-10-21-147-148:~$ sudo netstat -lapn | grep 22
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      597/sshd
tcp        0    144 10.21.147.148:22        188.162.39.11:52400     ESTABLISHED 1515/sshd: ubuntu [
tcp        0      0 10.21.147.148:22        188.162.39.11:51768     ESTABLISHED 1296/sshd: ubuntu [
tcp6       0      0 :::22                   :::*                    LISTEN      597/sshd

On my PC side when I hit Ctrl-C the output changes not much and is going to be the following:

DEBUG ssh: Sending SSH keep-alive...
^C INFO interface: warn: Waiting for cleanup before exiting...
 INFO interface: warn: ==> default: Waiting for cleanup before exiting...
==> default: Waiting for cleanup before exiting...
DEBUG ssh: Sending SSH keep-alive...
DEBUG ssh: Sending SSH keep-alive...
...