vagrant-openstack-provider icon indicating copy to clipboard operation
vagrant-openstack-provider copied to clipboard

Published 20 hours ago • verified publisher icon ggiamarchi

Problem SSHing into instance using floating IP

Open jfbibeau opened this issue 8 years ago • 5 comments

Hi there,

I'm trying to use the functionality of this plugin where it should automatically use the floating IP to try to SSH, but this doesn't appear to be working.

Here's some output, which has some weirdness:

Bringing machine 'latest' up with 'openstack' provider...
==>latest: Finding flavor for server...
==>latest: Finding image for server...
==>latest: Finding network(s) for server...
==>latest: Launching a server with the following settings...
==>latest:  -- Tenant          : infrastructure
==>latest:  -- Name            :latest
==>latest:  -- Flavor          : vagrant-slave
==>latest:  -- FlavorRef       : d6fee470-76b4-44c9-872b-dbaaeb717d7a
==>latest:  -- Image           : redhat-7.2_chef-12.5.1
==>latest:  -- ImageRef        : b6c0288e-7323-4c17-b483-e6aef5e670e0
==>latest:  -- KeyPair         : vagrant-generated-faebvnsq
==>latest:  -- Network         : 5c0d7287-e17d-4d8a-9808-34c238673912
==>latest: Waiting for the server to be built...
==>latest: Using floating IP 138.120.119.172
==>latest: Waiting for SSH to become available...
ssh: connect to host 10.0.0.7 port 22: Connection timed out
ssh: connect to host 10.0.0.7 port 22: Connection timed out
^C==>latest: Waiting for cleanup before exiting...
ssh: connect to host 10.0.0.7 port 22: Connection timed out
==>latest: Timeout!
SSH server unavailable on instance 138.120.119.173. You should maybe increase the timeout value which currently is 180 second(s).

Note is says "using floating IP 138.120.119.172" which is good, that's what I see assigned in OpenStack.. However it's trying to SSH using 10.0.0.7, which is the private IP...

And finally, at the end, it says "SSH server unavailable on instance 138.120.119.173" - which is 1 digit above the floating IP that was assigned?!

This is my config...

    os.openstack_auth_url = 'http://138.120.119.161:5000/v2.0/tokens'
    os.floating_ip_pool = [ 'ext-net' ]
    os.username = 'xxx'
    os.password = 'xxx'
    os.tenant_name = 'infrastructure'
    os.flavor = 'vagrant-slave'
    os.image = 'redhat-7.2_chef-12.5.1'
    os.networks = [ 'infrastructure-net' ]

jfbibeau avatar Mar 31 '16 15:03 jfbibeau

Added the last lines before it times out, when it's bringing the machine up...

2016-03-31 13:34 | DEBUG | Searching for available ips
2016-03-31 13:34 | DEBUG | Retrieving all allocated floating ips on tenant
2016-03-31 13:34 | DEBUG | get_all_floating_ips - start
2016-03-31 13:34 | DEBUG | request  => method  : GET
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/os-floating-ips
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json}
2016-03-31 13:34 | DEBUG | response => code    : 200
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"application/json", :content_length=>"280", :x_compute_request_id=>"req-cb82222f-500d-4e8a-a6cc-21ee0eb7a407", :date=>"Thu, 31 Mar 2016 17:34:38 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive", :age=>"0"}
2016-03-31 13:34 | DEBUG | response => body    : {"floating_ips": [{"instance_id": null, "ip": "138.120.119.172", "fixed_ip": null, "id": "1558b576-098f-45a1-b81e-83ac93e50523", "pool": "ext-net"}, {"instance_id": null, "ip": "138.120.119.173", "fixed_ip": null, "id": "ef5a0c58-f542-46de-8c1c-d7622748a0f6", "pool": "ext-net"}]}
2016-03-31 13:34 | DEBUG | get_all_floating_ips - end
2016-03-31 13:34 | DEBUG | 138.120.119.172 not attached
2016-03-31 13:34 |  INFO | Using floating IP 138.120.119.172
==> nsp-latest: Using floating IP 138.120.119.172
2016-03-31 13:34 | DEBUG | check_floating_ip - start
2016-03-31 13:34 | DEBUG | request  => method  : GET
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/os-floating-ips
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json}
2016-03-31 13:34 | DEBUG | response => code    : 200
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"application/json", :content_length=>"280", :x_compute_request_id=>"req-cb82222f-500d-4e8a-a6cc-21ee0eb7a407", :date=>"Thu, 31 Mar 2016 17:34:38 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive", :age=>"0"}
2016-03-31 13:34 | DEBUG | response => body    : {"floating_ips": [{"instance_id": null, "ip": "138.120.119.172", "fixed_ip": null, "id": "1558b576-098f-45a1-b81e-83ac93e50523", "pool": "ext-net"}, {"instance_id": null, "ip": "138.120.119.173", "fixed_ip": null, "id": "ef5a0c58-f542-46de-8c1c-d7622748a0f6", "pool": "ext-net"}]}
2016-03-31 13:34 | DEBUG | check_floating_ip - end
2016-03-31 13:34 | DEBUG | block in add_floating_ip - start
2016-03-31 13:34 | DEBUG | request  => method  : POST
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1/action
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json, :content_type=>:json}
2016-03-31 13:34 | DEBUG | request  => body    : {"addFloatingIp":{"address":"138.120.119.172"}}
2016-03-31 13:34 | DEBUG | response => code    : 202
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"text/html; charset=UTF-8", :content_length=>"0", :x_compute_request_id=>"req-c3480d22-ae49-47d2-9a9e-a1e0f03daea8", :date=>"Thu, 31 Mar 2016 17:34:42 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive"}
2016-03-31 13:34 | DEBUG | response => body    : 
2016-03-31 13:34 | DEBUG | block in add_floating_ip - end
2016-03-31 13:34 | DEBUG | Checking if SSH port is open... Attempt number 0
2016-03-31 13:34 |  INFO | Waiting for SSH to become available...
==> nsp-latest: Waiting for SSH to become available...
2016-03-31 13:34 |  INFO | Reading SSH info
2016-03-31 13:34 | DEBUG | block in get_server_details - start
2016-03-31 13:34 | DEBUG | request  => method  : GET
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json}
2016-03-31 13:34 | DEBUG | response => code    : 200
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"application/json", :content_length=>"1654", :x_compute_request_id=>"req-82abd6f3-49f9-44ab-8a86-7f1648274d67", :date=>"Thu, 31 Mar 2016 17:34:35 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive", :age=>"7"}
2016-03-31 13:34 | DEBUG | response => body    : {"server": {"status": "ACTIVE", "updated": "2016-03-31T17:34:28Z", "hostId": "eafc253d2e8f36008adae27a0947233ee4db34eff1a233ae2545111a", "addresses": {"infrastructure-net": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:18:a8:30", "version": 4, "addr": "10.0.0.12", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "rel": "self"}, {"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "rel": "bookmark"}], "key_name": "vagrant-generated-bljzhkoy", "image": {"id": "cfcc12aa-2f78-4c53-a1c8-bee443ebf647", "links": [{"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/images/cfcc12aa-2f78-4c53-a1c8-bee443ebf647", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2016-03-31T17:34:28.000000", "flavor": {"id": "d6fee470-76b4-44c9-872b-dbaaeb717d7a", "links": [{"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/flavors/d6fee470-76b4-44c9-872b-dbaaeb717d7a", "rel": "bookmark"}]}, "id": "9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "539a1a1295af4126b5c871965d04607e", "name": "nsp-latest", "created": "2016-03-31T17:33:51Z", "tenant_id": "f0399f45cb6543a78776ef46f4ab8507", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}
2016-03-31 13:34 | DEBUG | block in get_server_details - end
2016-03-31 13:34 | DEBUG | block in get_server_details - start
2016-03-31 13:34 | DEBUG | request  => method  : GET
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json}
2016-03-31 13:34 | DEBUG | response => code    : 200
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"application/json", :content_length=>"1654", :x_compute_request_id=>"req-82abd6f3-49f9-44ab-8a86-7f1648274d67", :date=>"Thu, 31 Mar 2016 17:34:35 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive", :age=>"7"}
2016-03-31 13:34 | DEBUG | response => body    : {"server": {"status": "ACTIVE", "updated": "2016-03-31T17:34:28Z", "hostId": "eafc253d2e8f36008adae27a0947233ee4db34eff1a233ae2545111a", "addresses": {"infrastructure-net": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:18:a8:30", "version": 4, "addr": "10.0.0.12", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "rel": "self"}, {"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "rel": "bookmark"}], "key_name": "vagrant-generated-bljzhkoy", "image": {"id": "cfcc12aa-2f78-4c53-a1c8-bee443ebf647", "links": [{"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/images/cfcc12aa-2f78-4c53-a1c8-bee443ebf647", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2016-03-31T17:34:28.000000", "flavor": {"id": "d6fee470-76b4-44c9-872b-dbaaeb717d7a", "links": [{"href": "http://138.120.119.161:8774/f0399f45cb6543a78776ef46f4ab8507/flavors/d6fee470-76b4-44c9-872b-dbaaeb717d7a", "rel": "bookmark"}]}, "id": "9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "539a1a1295af4126b5c871965d04607e", "name": "nsp-latest", "created": "2016-03-31T17:33:51Z", "tenant_id": "f0399f45cb6543a78776ef46f4ab8507", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}
2016-03-31 13:34 | DEBUG | block in get_server_details - end
ssh: connect to host 10.0.0.12 port 22: Connection timed out
2016-03-31 13:35 | DEBUG | SSH not yet available... new retry in in 1 second
2016-03-31 13:35 | DEBUG | Checking if SSH port is open... Attempt number 1
2016-03-31 13:35 |  INFO | Reading SSH info
ssh: connect to host 10.0.0.12 port 22: Connection timed out
2016-03-31 13:36 | DEBUG | SSH not yet available... new retry in in 1 second
2016-03-31 13:36 | DEBUG | Checking if SSH port is open... Attempt number 2
2016-03-31 13:36 |  INFO | Reading SSH info
ssh: connect to host 10.0.0.12 port 22: Connection timed out
2016-03-31 13:37 | DEBUG | SSH not yet available... new retry in in 1 second
==> nsp-latest: Timeout!
2016-03-31 13:37 | DEBUG | Searching for available ips
2016-03-31 13:37 | DEBUG | Retrieving all allocated floating ips on tenant
2016-03-31 13:37 | DEBUG | get_all_floating_ips - start
2016-03-31 13:37 | DEBUG | request  => method  : GET
2016-03-31 13:37 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/os-floating-ips
2016-03-31 13:37 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json}
2016-03-31 13:37 | DEBUG | response => code    : 200
2016-03-31 13:37 | DEBUG | response => headers : {:content_type=>"application/json", :content_length=>"321", :x_compute_request_id=>"req-12ab932c-b9c4-44f9-8de1-71b8d1ff11e7", :date=>"Thu, 31 Mar 2016 17:37:56 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive", :age=>"0"}
2016-03-31 13:37 | DEBUG | response => body    : {"floating_ips": [{"instance_id": "9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1", "ip": "138.120.119.172", "fixed_ip": "10.0.0.12", "id": "1558b576-098f-45a1-b81e-83ac93e50523", "pool": "ext-net"}, {"instance_id": null, "ip": "138.120.119.173", "fixed_ip": null, "id": "ef5a0c58-f542-46de-8c1c-d7622748a0f6", "pool": "ext-net"}]}
2016-03-31 13:37 | DEBUG | get_all_floating_ips - end
2016-03-31 13:37 | DEBUG | 138.120.119.172 attached to 9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1
2016-03-31 13:37 | DEBUG | 138.120.119.173 not attached
SSH server unavailable on instance 138.120.119.173. You should maybe increase the timeout value which currently is 180 second(s).

SSH manually works fine using ssh [email protected]...

jfbibeau avatar Mar 31 '16 17:03 jfbibeau

Note: vagrant ssh, vagrant provision work fine... Weird eh?

jfbibeau avatar Mar 31 '16 23:03 jfbibeau

Okay, don't pay attention to the wrong address in the final error mesage. This is a bug i just file https://github.com/ggiamarchi/vagrant-openstack-provider/issues/279 but this is not related to your main problem.

To understand why Vagrant tries to SSH the private IP, let me explain the implemented workflow. Vagrant never stores the floating IP information when it associates it to the instance. Instead, it retrieves it through the nova API on each vagrant command. This way, even if the floating IP is changed manually after machine creation, vagrant will always be able to deal with it.

To retrieve the floating IP, Vagrant looks for the IP addresses form the server details. We can see in your logs that there's only the private IP.

"addresses": {
  "infrastructure-net": [
    {
      "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:18:a8:30",
      "version": 4,
      "addr": "10.0.0.12",
      "OS-EXT-IPS:type": "fixed"
    }
  ]
}

Normally, there should be also the floating IP with a OS-EXT-IPS:type set to floating. Here, vagrant don't find it and fallbacks to the only IP it found.

I don't remember how exactly it works in OpenStack, but i remember i have ever seen a situation where it takes a very long time after the floating IP association to see the floating IP information through the nova API. Maybe this is your case and this could explain why a bit later the vagrant ssh works fine.

ggiamarchi avatar Apr 05 '16 12:04 ggiamarchi

Hmm yes, I see what you mean. I will try to do the test again while doing a curl call to the nova api to see when the floating IP starts showing up.

Just an idea: I am wondering if we can optimize a bit, since we already know what the floating IP is on initial provision (notice: addFloatingIp command sends the actual floating IP):

2016-03-31 13:34 | DEBUG | block in add_floating_ip - start
2016-03-31 13:34 | DEBUG | request  => method  : POST
2016-03-31 13:34 | DEBUG | request  => url     : http://138.120.119.161:8774/v2/f0399f45cb6543a78776ef46f4ab8507/servers/9b9dc708-e427-45a4-8a6c-29d4a9a0bbc1/action
2016-03-31 13:34 | DEBUG | request  => headers : {"X-Auth-Token"=>"90da99aff1d343b7b42ebd857f7c2e6b", :accept=>:json, :content_type=>:json}
2016-03-31 13:34 | DEBUG | request  => body    : {"addFloatingIp":{"address":"138.120.119.172"}}
2016-03-31 13:34 | DEBUG | response => code    : 202
2016-03-31 13:34 | DEBUG | response => headers : {:content_type=>"text/html; charset=UTF-8", :content_length=>"0", :x_compute_request_id=>"req-c3480d22-ae49-47d2-9a9e-a1e0f03daea8", :date=>"Thu, 31 Mar 2016 17:34:42 GMT", :proxy_connection=>"Keep-Alive", :connection=>"Keep-Alive"}
2016-03-31 13:34 | DEBUG | response => body    : 
2016-03-31 13:34 | DEBUG | block in add_floating_ip - end

The problem is without the initial ssh working, vagrant up always fails in error, so it is not ideal...

Another option would be to call get_server_details to refresh IP information between SSH attempts, so that you give a chance between SSH attempts to re-query nova and get the floating IP?

What do you think?

jfbibeau avatar Apr 05 '16 13:04 jfbibeau

@ggiamarchi For what it's worth this was working fine in 0.6.0 of the plugin, so looks like a regression of some sort.

jfbibeau avatar Apr 08 '16 20:04 jfbibeau