Open jfbibeau opened 8 years ago
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 vagrant@138.120.119.172
...
Note: vagrant ssh, vagrant provision work fine... Weird eh?
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.
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?
@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.
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:
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...