Changes need to redeploy to take effect

sunshineo commented 7 years ago

According to https://github.com/docker/dockercloud-haproxy#settings-in-linked-application-services

Settings here can overwrite the settings in HAProxy, which are only applied to the linked services. If run in Docker Cloud, when the service redeploys, joins or leaves HAProxy service, HAProxy service will automatically update itself to apply the changes

That is not what I'm experiencing at all. When I link a new service, I have to re-deploy haproxy to make it work.

h0lyalg0rithm commented 7 years ago

Same here when ever we make changes to the container, we have redeploy the load balancer for it to recognize the machines.

sunshineo commented 7 years ago

Hello! Please have a look at this. This may not be haproxy problem but something wrong with docker cloud network.

vyrak commented 7 years ago

I am experience the same thing on version 1.5.3. When one of my linked services gets redeployed, HAProxy sees the service go down, but will not update when the service comes back up.

sunshineo commented 7 years ago

Feels like we are getting abandoned. Anyone know if we should go with nginx? Does dockercloud have good support for it?

cosmostail commented 7 years ago

@sunshineo I switched to https://github.com/madwire/dockercloud-nginx-proxy which works perfectly.. even without much documentation to go on... If you have multiple domains, just remember instead using "," separator, using "space".

sunshineo commented 7 years ago

Thank you @cosmostail !

sunshineo commented 7 years ago

For the root cause of this problem, I'm feeling that the docker cloud link thing is pretty bad https://docs.docker.com/docker-cloud/apps/service-links/

sunshineo commented 7 years ago

Maybe we just missed this part https://github.com/docker/dockercloud-haproxy#running-in-docker-cloud

Full Access

tifayuki commented 7 years ago

@sunshineo

dockercloud/haproxy uses Docker Cloud API to monitor if there is any changes in the container itself as well as its linked containers. (see: https://docs.docker.com/apidocs/docker-cloud/#api-roles)

As you said, given Full Access to dockercloud/haporxy is very important for the auto config change detection, which gives the container permission to access Docker Cloud API

When the api roles is set to global(using cli or stackfiles) or Full Access(in Web UI), you well see the following message in the first line of the log of dockercloud/haproxy: INFO:haproxy:dockercloud/haproxy 1.5.3 has access to the Docker Cloud API - will reload list of backends in real-time, indicating that the auto config detection is enabled.

sunshineo commented 7 years ago

@tifayuki I tried to give it "Full Access", then the haproxy dies once every day. I had to manually redeploy it and also specify "Do not reuse volume." for it to get back to normal.

kevinsmith commented 7 years ago

I can use dockercloud/cli to update the links, but only if haproxy has been restarted within the past few minutes. If it's been about a half-hour or more, I just get this in the log:

[lb-1]2017-02-16T21:02:05.838644097Z INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-1]2017-02-16T21:02:06.839938408Z INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-1]2017-02-16T21:02:06.840271523Z INFO:haproxy:==========BEGIN==========

It never moves past that point. The very next step should be haproxy reading back the newly linked service and starting its new configuration. It's like it just gets stuck if it's been running for any time at all.

Any thoughts, @tifayuki?

tifayuki commented 7 years ago

@kevinsmith Not sure what happened. Is this error reproducible?

kevinsmith commented 7 years ago

Yes, it's consistent. I'll see if I can come up with a fully reproducible setup for you.

Worth noting that I just redeployed 2 of the 4 services on this loadbalancer (the 2 for staging.example.com, so downtime during deploy is insignificant), and haproxy picked up the changes with those services just fine. After reconfiguring itself, it printed this to the log and then stopped:

[lb-2]2017-02-16T20:47:29.027605297Z INFO:haproxy:Launching HAProxy
[lb-2]2017-02-16T20:47:29.031150076Z INFO:haproxy:HAProxy has been launched(PID: 13)
[lb-2]2017-02-16T20:47:29.031319884Z INFO:haproxy:===========END===========
[lb-2]2017-02-16T21:02:05.874422810Z INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-2]2017-02-16T21:02:06.875819179Z INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-2]2017-02-16T21:02:06.876686923Z INFO:haproxy:==========BEGIN==========

So it's almost like the "change service links" event is stuck in a queue.

kevinsmith commented 7 years ago

This stuff showed up in the log while I was away. Seems like it might be relevant to this issue. (You'll notice the first 6 lines are the same as in the last post.)

[lb-2]2017-02-16T20:47:29.027605297Z INFO:haproxy:Launching HAProxy
[lb-2]2017-02-16T20:47:29.031150076Z INFO:haproxy:HAProxy has been launched(PID: 13)
[lb-2]2017-02-16T20:47:29.031319884Z INFO:haproxy:===========END===========
[lb-2]2017-02-16T21:02:05.874422810Z INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-2]2017-02-16T21:02:06.875819179Z INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container
[lb-2]2017-02-16T21:02:06.876686923Z INFO:haproxy:==========BEGIN==========
[lb-2]2017-02-16T21:17:46.136377572Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)
[lb-2]2017-02-16T21:33:31.289393024Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)
[lb-2]2017-02-16T21:43:26.507755919Z INFO:haproxy:=> Add task: Docker Cloud Event: container 6d0a15a1-19f1-4b94-b369-2a3cbfdaef3a is terminated
[lb-2]2017-02-16T21:43:26.620500616Z INFO:haproxy:=> Add task: Docker Cloud Event: container 0a2fb5d6-b33f-4331-a846-4444ea1fec87 is running
[lb-2]2017-02-16T21:43:44.402541358Z INFO:haproxy:=> Add task: Docker Cloud Event: container f6fb319b-ca7b-45b6-baef-c3d7bcbcb62e is terminated
[lb-2]2017-02-16T21:43:44.484142381Z INFO:haproxy:=> Add task: Docker Cloud Event: container 87026880-66a1-4062-90bc-30ef0d03db8c is running
[lb-2]2017-02-16T21:43:50.221953815Z INFO:haproxy:=> Add task: Docker Cloud Event: container 74906785-d103-4965-8af5-c189e1f4db80 is terminated
[lb-2]2017-02-16T21:43:50.309870757Z INFO:haproxy:=> Add task: Docker Cloud Event: container 5517c467-ad2a-4eb4-a433-ec682062b346 is running
[lb-2]2017-02-16T21:43:56.020723127Z INFO:haproxy:=> Add task: Docker Cloud Event: container 60c4f581-0d67-49ff-aece-9c8fe432e4b8 is terminated
[lb-2]2017-02-16T21:43:56.169869264Z INFO:haproxy:=> Add task: Docker Cloud Event: container f3cab75a-dcec-4657-8685-c0f78e332955 is running
[lb-2]2017-02-16T21:44:02.194943410Z INFO:haproxy:=> Add task: Docker Cloud Event: container 7bf8a84e-21d0-40d1-92b2-7033473fa592 is terminated
[lb-2]2017-02-16T21:44:02.272112409Z INFO:haproxy:=> Add task: Docker Cloud Event: container 1c52a6a1-6fe7-4e61-b460-e647755c2129 is running
[lb-2]2017-02-16T21:44:08.392928991Z INFO:haproxy:=> Add task: Docker Cloud Event: container 7c6a279b-1d9c-43b5-91b1-2f853fbc6058 is terminated
[lb-2]2017-02-16T21:44:08.517030762Z INFO:haproxy:=> Add task: Docker Cloud Event: container 9bbb247f-0510-4159-841e-89a0c96054a2 is running
[lb-2]2017-02-16T21:44:14.185886805Z INFO:haproxy:=> Add task: Docker Cloud Event: container 287889e5-b2cb-452e-b8bb-6a79a37b296d is terminated
[lb-2]2017-02-16T21:44:14.285611844Z INFO:haproxy:=> Add task: Docker Cloud Event: container d39e311f-0bbd-4a54-8e69-92eb422b5f7a is running
[lb-2]2017-02-16T21:44:19.839943599Z INFO:haproxy:=> Add task: Docker Cloud Event: container 42d0f708-02cb-4f77-ba64-c5f1cdeaaf15 is terminated
[lb-2]2017-02-16T21:44:19.953873156Z INFO:haproxy:=> Add task: Docker Cloud Event: container 661e5d94-5779-4040-be86-650302b72ca4 is running
[lb-2]2017-02-16T21:44:25.546063022Z INFO:haproxy:=> Add task: Docker Cloud Event: container e0b6a451-eb11-46d6-8ed0-139e10f9411b is terminated
[lb-2]2017-02-16T21:44:25.674982436Z INFO:haproxy:=> Add task: Docker Cloud Event: container 11a1824f-bb57-4e11-a4aa-a53e14be795c is running
[lb-2]2017-02-16T21:44:31.208420433Z INFO:haproxy:=> Add task: Docker Cloud Event: container 2ae8e445-881e-4797-b47f-908f658ef504 is terminated
[lb-2]2017-02-16T21:44:31.420293139Z INFO:haproxy:=> Add task: Docker Cloud Event: container 46c56409-cd7f-41b5-ab5d-b5fbde973790 is running
[lb-2]2017-02-16T21:45:05.255590657Z INFO:haproxy:=> Add task: Docker Cloud Event: container 9485dfab-5d57-48a7-acee-83572abf2525 is terminated
[lb-2]2017-02-16T21:45:05.357305096Z INFO:haproxy:=> Add task: Docker Cloud Event: container 4ff7a109-4f80-464b-ae37-22d9daba0e47 is running
[lb-2]2017-02-16T21:45:34.088271865Z INFO:haproxy:=> Add task: Docker Cloud Event: container 27275484-b50a-4eb6-b6df-c558e369b810 is running
[lb-2]2017-02-16T21:45:34.198643742Z INFO:haproxy:=> Add task: Docker Cloud Event: container 92c83b7d-9157-4ce7-a7c0-d28a93141f77 is terminated
[lb-2]2017-02-16T21:45:40.022667904Z INFO:haproxy:=> Add task: Docker Cloud Event: container 86221389-a72a-41c8-a2ac-992a9d8930c2 is terminated
[lb-2]2017-02-16T21:45:40.124636056Z INFO:haproxy:=> Add task: Docker Cloud Event: container 9db5d8af-4981-4d0e-b72b-4b7606369d4d is running
[lb-2]2017-02-16T21:45:46.101680047Z INFO:haproxy:=> Add task: Docker Cloud Event: container 28a39900-7292-4195-83b5-914a01c4c240 is terminated
[lb-2]2017-02-16T21:45:46.199584794Z INFO:haproxy:=> Add task: Docker Cloud Event: container 529b2b38-521d-4d10-a671-1261b5f8f88d is running
[lb-2]2017-02-16T21:45:52.532912085Z INFO:haproxy:=> Add task: Docker Cloud Event: container 7310806e-2097-47db-ab03-9ddfe3818308 is terminated
[lb-2]2017-02-16T21:45:52.708868176Z INFO:haproxy:=> Add task: Docker Cloud Event: container 00b7fdb3-0a4f-4d92-93e9-325114e5a33e is running
[lb-2]2017-02-16T21:45:58.451972644Z INFO:haproxy:=> Add task: Docker Cloud Event: container ba5642e9-f5f3-4e85-b10a-748f324df820 is terminated
[lb-2]2017-02-16T21:45:58.481784451Z INFO:haproxy:=> Add task: Docker Cloud Event: container fa0d41a8-df5e-4113-bf5f-c9ecbed35fda is running
[lb-2]2017-02-16T21:46:04.757298318Z INFO:haproxy:=> Add task: Docker Cloud Event: container 5c3cc52f-ff2a-401d-8317-00dce5c64d7b is terminated
[lb-2]2017-02-16T21:46:04.805731065Z INFO:haproxy:=> Add task: Docker Cloud Event: container 7aa6d3a1-5554-49e5-abf5-735f67e640f1 is running
[lb-2]2017-02-16T21:46:11.602302456Z INFO:haproxy:=> Add task: Docker Cloud Event: container fe17e6db-0a29-4232-8550-b007482c8bf1 is terminated
[lb-2]2017-02-16T21:46:11.761185283Z INFO:haproxy:=> Add task: Docker Cloud Event: container 93cb03a6-2eb9-4339-a525-61a7c0400c79 is running
[lb-2]2017-02-16T21:46:18.437963320Z INFO:haproxy:=> Add task: Docker Cloud Event: container b0ab2161-da10-476d-8a79-1e653c0a050c is terminated
[lb-2]2017-02-16T21:46:18.505766646Z INFO:haproxy:=> Add task: Docker Cloud Event: container 85ac39c3-7e50-4941-9285-b2fd2b936197 is running
[lb-2]2017-02-16T21:46:25.249583468Z INFO:haproxy:=> Add task: Docker Cloud Event: container 18eca8db-0a34-4fa4-bf45-c49f31794fa5 is terminated
[lb-2]2017-02-16T21:46:25.440809529Z INFO:haproxy:=> Add task: Docker Cloud Event: container db1ec1e1-52cc-40e8-8593-635d36a4a86b is running
[lb-2]2017-02-16T21:49:16.440969829Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)
[lb-2]2017-02-16T22:05:01.591412836Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)
[lb-1]2017-02-16T21:46:11.770226346Z INFO:haproxy:=> Add task: Docker Cloud Event: container 93cb03a6-2eb9-4339-a525-61a7c0400c79 is running
[lb-1]2017-02-16T21:46:18.391144617Z INFO:haproxy:=> Add task: Docker Cloud Event: container b0ab2161-da10-476d-8a79-1e653c0a050c is terminated
[lb-1]2017-02-16T21:46:18.506224568Z INFO:haproxy:=> Add task: Docker Cloud Event: container 85ac39c3-7e50-4941-9285-b2fd2b936197 is running
[lb-1]2017-02-16T21:46:25.244223984Z INFO:haproxy:=> Add task: Docker Cloud Event: container 18eca8db-0a34-4fa4-bf45-c49f31794fa5 is terminated
[lb-1]2017-02-16T21:46:25.436299816Z INFO:haproxy:=> Add task: Docker Cloud Event: container db1ec1e1-52cc-40e8-8593-635d36a4a86b is running
[lb-1]2017-02-16T21:49:16.808666899Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)
[lb-1]2017-02-16T22:05:01.957919098Z INFO:haproxy:HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)

tifayuki commented 7 years ago

@kevinsmith

I saw this in the log: HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=None)

When an task is picked up and executed, the script tries to connect to docker cloud API to fetch information for reconfiguration. From the error, you can see that the request got timed out, That is why the script stopped updating and got stuck(it kept re-trying to connect to the server, but failed.).

There was a server update on Docker Cloud hours ago. No sure, but I think it may be related to that. Look like it is more like a network connectivity issue. Can you try to restart the haproxy container to see if everything back to work?

Thank you.

kevinsmith commented 7 years ago

Yeah, sounds like there may be the network issue. Just sent Docker an email support request about it.

The weird part is that the issue consistently fits this pattern:

Getting timeouts over and over, so HAProxy containers aren't reconfiguring
Restart the HAProxy containers
No timeouts, HAProxy is reconfiguring as expected
Works as expected through multiple service link changes for at least 30 minutes
At some point, HAProxy can no longer poll cloud.docker.com and it stops reconfiguring itself

Testing a few things now to see if I can get more detail on that pattern.

One question: why does the call to cloud.docker.com have such a long (15 minute) timeout?

kevinsmith commented 7 years ago

Just spend several hours testing, and there's a much clearer pattern:

Changing service links via dockercloud/cli works 100% of the time as long as it's done within 4 minutes 20 seconds of the most recent deploy/reconfiguration. (Yes, any service link change that took place in less than 4:20 time lapsed was successful 100% of the time, anything over failed.)
Total time since HAProxy container start doesn't matter, as long as the above condition is met. (In one test, I was able to keep reconfiguring the HAProxy container for over an hour -- 0 failures -- because the time between each service link update was less than 4:20.)

From those results, this is looking like less and less of a network issue on Docker Cloud's part. Something is happening around the 4:20 mark that's causing them to no longer be able to poll the Docker Cloud API. If that's the case, it would explain why this condition always slips through testing.

Could you try it out by waiting longer than 4:20 to update the service links and see if the HAProxy container is able to poll the API?

tifayuki commented 7 years ago

@kevinsmith

Thanks for the testing.

why does the call to cloud.docker.com have such a long (15 minute) timeout? I didn't set the timeout. The value is None by default in python library, and seems to be 15 mins in your test.
4'20" Polling issue

I don't know where/why does the magic number 4:20 come from. The behavior of haproxy looks weird. I did some tests myself and you can see the logs below.

Created the haproxy service linked to hello at 21:43:33
Removed the hello link and add world link at 21:55:08
Removed the world link and add back hello link at 22:03:15

The interval between each operation is longer than 4'12" but I didn't see any error. Cannot reproduce on my side :(

BTW, my node is deployed usingdigital ocean inNew York 2 zone


[haproxy-1]2017-02-17T21:43:33.694903684Z INFO:haproxy:dockercloud/haproxy PID: 5
[haproxy-1]2017-02-17T21:43:33.859599427Z INFO:haproxy:=> Add task: Websocket open
[haproxy-1]2017-02-17T21:43:34.861286173Z INFO:haproxy:=> Executing task: Websocket open
[haproxy-1]2017-02-17T21:43:34.861574393Z INFO:haproxy:==========BEGIN==========
[haproxy-1]2017-02-17T21:43:35.818112026Z INFO:haproxy:Linked service: HELLO(97026759-4a56-4c92-8915-7a902cb196c6)
[haproxy-1]2017-02-17T21:43:35.818751167Z INFO:haproxy:Linked container: HELLO_1(bc8ab9af-e958-47b3-ad7f-dbd3c45a5283)
[haproxy-1]2017-02-17T21:43:35.820860995Z INFO:haproxy:HAProxy configuration:
[haproxy-1]2017-02-17T21:43:35.820914375Z global
[haproxy-1]2017-02-17T21:43:35.820937535Z   log 127.0.0.1 local0
[haproxy-1]2017-02-17T21:43:35.820955978Z   log 127.0.0.1 local1 notice
[haproxy-1]2017-02-17T21:43:35.820972360Z   log-send-hostname
[haproxy-1]2017-02-17T21:43:35.820988213Z   maxconn 4096
[haproxy-1]2017-02-17T21:43:35.821004025Z   pidfile /var/run/haproxy.pid
[haproxy-1]2017-02-17T21:43:35.821021135Z   user haproxy
[haproxy-1]2017-02-17T21:43:35.821038863Z   group haproxy
[haproxy-1]2017-02-17T21:43:35.821056938Z   daemon
[haproxy-1]2017-02-17T21:43:35.821074745Z   stats socket /var/run/haproxy.stats level admin
[haproxy-1]2017-02-17T21:43:35.821094978Z   ssl-default-bind-options no-sslv3
[haproxy-1]2017-02-17T21:43:35.821117240Z   ssl-default-bind-ciphers ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:AES128-GCM-SHA256:AES128-SHA256:AES128-SHA:AES256-GCM-SHA384:AES256-SHA256:AES256-SHA:DHE-DSS-AES128-SHA:DES-CBC3-SHA
[haproxy-1]2017-02-17T21:43:35.821144208Z defaults
[haproxy-1]2017-02-17T21:43:35.821154095Z   balance roundrobin
[haproxy-1]2017-02-17T21:43:35.821163275Z   log global
[haproxy-1]2017-02-17T21:43:35.821172660Z   mode http
[haproxy-1]2017-02-17T21:43:35.821181935Z   option redispatch
[haproxy-1]2017-02-17T21:43:35.821191003Z   option httplog
[haproxy-1]2017-02-17T21:43:35.821199820Z   option dontlognull
[haproxy-1]2017-02-17T21:43:35.821208815Z   option forwardfor
[haproxy-1]2017-02-17T21:43:35.821217795Z   timeout connect 5000
[haproxy-1]2017-02-17T21:43:35.821227005Z   timeout client 50000
[haproxy-1]2017-02-17T21:43:35.821236055Z   timeout server 50000
[haproxy-1]2017-02-17T21:43:35.821245438Z listen stats
[haproxy-1]2017-02-17T21:43:35.821265260Z   bind :1936
[haproxy-1]2017-02-17T21:43:35.821282128Z   mode http
[haproxy-1]2017-02-17T21:43:35.821326475Z   stats enable
[haproxy-1]2017-02-17T21:43:35.821344420Z   timeout connect 10s
[haproxy-1]2017-02-17T21:43:35.821360743Z   timeout client 1m
[haproxy-1]2017-02-17T21:43:35.821377248Z   timeout server 1m
[haproxy-1]2017-02-17T21:43:35.821425183Z   stats hide-version
[haproxy-1]2017-02-17T21:43:35.821450985Z   stats realm Haproxy\ Statistics
[haproxy-1]2017-02-17T21:43:35.821471945Z   stats uri /
[haproxy-1]2017-02-17T21:43:35.821490778Z   stats auth stats:stats
[haproxy-1]2017-02-17T21:43:35.821500495Z frontend default_port_80
[haproxy-1]2017-02-17T21:43:35.821509658Z   bind :80
[haproxy-1]2017-02-17T21:43:35.821518565Z   reqadd X-Forwarded-Proto:\ http
[haproxy-1]2017-02-17T21:43:35.821527808Z   maxconn 4096
[haproxy-1]2017-02-17T21:43:35.821536765Z   default_backend default_service
[haproxy-1]2017-02-17T21:43:35.821545953Z backend default_service
[haproxy-1]2017-02-17T21:43:35.821555105Z   server HELLO_1 10.7.0.2:80 check inter 2000 rise 2 fall 3
[haproxy-1]2017-02-17T21:43:35.822508706Z INFO:haproxy:Launching HAProxy
[haproxy-1]2017-02-17T21:43:35.831008699Z INFO:haproxy:HAProxy has been launched(PID: 13)
[haproxy-1]2017-02-17T21:43:35.831514997Z INFO:haproxy:===========END===========
[haproxy-1]2017-02-17T21:55:08.789552118Z INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
[haproxy-1]2017-02-17T21:55:09.792721512Z INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container
[haproxy-1]2017-02-17T21:55:09.793310146Z INFO:haproxy:==========BEGIN==========
[haproxy-1]2017-02-17T21:55:10.158635407Z INFO:haproxy:Linked service: WORLD(57eb913e-7868-4dae-8e27-6254371ff515)
[haproxy-1]2017-02-17T21:55:10.159279374Z INFO:haproxy:Linked container: WORLD_1(9cc62c89-85d2-4ed8-9245-5d23720d0c1b)
[haproxy-1]2017-02-17T21:55:10.161678818Z INFO:haproxy:HAProxy configuration:
[haproxy-1]2017-02-17T21:55:10.161738735Z global
[haproxy-1]2017-02-17T21:55:10.161753791Z   log 127.0.0.1 local0
[haproxy-1]2017-02-17T21:55:10.161766008Z   log 127.0.0.1 local1 notice
[haproxy-1]2017-02-17T21:55:10.161777935Z   log-send-hostname
[haproxy-1]2017-02-17T21:55:10.161789501Z   maxconn 4096
[haproxy-1]2017-02-17T21:55:10.161800855Z   pidfile /var/run/haproxy.pid
[haproxy-1]2017-02-17T21:55:10.161811945Z   user haproxy
[haproxy-1]2017-02-17T21:55:10.161823138Z   group haproxy
[haproxy-1]2017-02-17T21:55:10.161834135Z   daemon
[haproxy-1]2017-02-17T21:55:10.161846345Z   stats socket /var/run/haproxy.stats level admin
[haproxy-1]2017-02-17T21:55:10.161858181Z   ssl-default-bind-options no-sslv3
[haproxy-1]2017-02-17T21:55:10.161885368Z   ssl-default-bind-ciphers ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:AES128-GCM-SHA256:AES128-SHA256:AES128-SHA:AES256-GCM-SHA384:AES256-SHA256:AES256-SHA:DHE-DSS-AES128-SHA:DES-CBC3-SHA
[haproxy-1]2017-02-17T21:55:10.161900568Z defaults
[haproxy-1]2017-02-17T21:55:10.161948335Z   balance roundrobin
[haproxy-1]2017-02-17T21:55:10.161960812Z   log global
[haproxy-1]2017-02-17T21:55:10.161972198Z   mode http
[haproxy-1]2017-02-17T21:55:10.162024732Z   option redispatch
[haproxy-1]2017-02-17T21:55:10.162047942Z   option httplog
[haproxy-1]2017-02-17T21:55:10.162058922Z   option dontlognull
[haproxy-1]2017-02-17T21:55:10.162069538Z   option forwardfor
[haproxy-1]2017-02-17T21:55:10.162080055Z   timeout connect 5000
[haproxy-1]2017-02-17T21:55:10.162090488Z   timeout client 50000
[haproxy-1]2017-02-17T21:55:10.162100785Z   timeout server 50000
[haproxy-1]2017-02-17T21:55:10.162111275Z listen stats
[haproxy-1]2017-02-17T21:55:10.162121595Z   bind :1936
[haproxy-1]2017-02-17T21:55:10.162131985Z   mode http
[haproxy-1]2017-02-17T21:55:10.162142312Z   stats enable
[haproxy-1]2017-02-17T21:55:10.162152598Z   timeout connect 10s
[haproxy-1]2017-02-17T21:55:10.162162995Z   timeout client 1m
[haproxy-1]2017-02-17T21:55:10.162173472Z   timeout server 1m
[haproxy-1]2017-02-17T21:55:10.162183882Z   stats hide-version
[haproxy-1]2017-02-17T21:55:10.162194255Z   stats realm Haproxy\ Statistics
[haproxy-1]2017-02-17T21:55:10.162204995Z   stats uri /
[haproxy-1]2017-02-17T21:55:10.162215365Z   stats auth stats:stats
[haproxy-1]2017-02-17T21:55:10.162225845Z frontend default_port_80
[haproxy-1]2017-02-17T21:55:10.162236402Z   bind :80
[haproxy-1]2017-02-17T21:55:10.162246775Z   reqadd X-Forwarded-Proto:\ http
[haproxy-1]2017-02-17T21:55:10.162257372Z   maxconn 4096
[haproxy-1]2017-02-17T21:55:10.162267748Z   default_backend default_service
[haproxy-1]2017-02-17T21:55:10.162278205Z backend default_service
[haproxy-1]2017-02-17T21:55:10.162288705Z   server WORLD_1 10.7.0.3:80 check inter 2000 rise 2 fall 3
[haproxy-1]2017-02-17T21:55:10.163297529Z INFO:haproxy:Reloading HAProxy
[haproxy-1]2017-02-17T21:55:10.175427844Z INFO:haproxy:HAProxy has been reloaded(PID: 14)
[haproxy-1]2017-02-17T21:55:10.176173294Z INFO:haproxy:===========END===========
[haproxy-1]2017-02-17T21:55:10.188577303Z INFO:haproxy:HAProxy(PID:13) has been terminated
[haproxy-1]2017-02-17T22:03:15.823223668Z INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
[haproxy-1]2017-02-17T22:03:16.827641222Z INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container
[haproxy-1]2017-02-17T22:03:16.828376855Z INFO:haproxy:==========BEGIN==========
[haproxy-1]2017-02-17T22:03:17.133455993Z INFO:haproxy:Linked service: HELLO(97026759-4a56-4c92-8915-7a902cb196c6)
[haproxy-1]2017-02-17T22:03:17.134082106Z INFO:haproxy:Linked container: HELLO_1(bc8ab9af-e958-47b3-ad7f-dbd3c45a5283)
[haproxy-1]2017-02-17T22:03:17.141997283Z INFO:haproxy:HAProxy configuration:
[haproxy-1]2017-02-17T22:03:17.142036786Z global
[haproxy-1]2017-02-17T22:03:17.142051383Z   log 127.0.0.1 local0
[haproxy-1]2017-02-17T22:03:17.142063446Z   log 127.0.0.1 local1 notice
[haproxy-1]2017-02-17T22:03:17.142075419Z   log-send-hostname
[haproxy-1]2017-02-17T22:03:17.142087373Z   maxconn 4096
[haproxy-1]2017-02-17T22:03:17.142098686Z   pidfile /var/run/haproxy.pid
[haproxy-1]2017-02-17T22:03:17.142144806Z   user haproxy
[haproxy-1]2017-02-17T22:03:17.142159443Z   group haproxy
[haproxy-1]2017-02-17T22:03:17.142170440Z   daemon
[haproxy-1]2017-02-17T22:03:17.142182423Z   stats socket /var/run/haproxy.stats level admin
[haproxy-1]2017-02-17T22:03:17.142193406Z   ssl-default-bind-options no-sslv3
[haproxy-1]2017-02-17T22:03:17.142217203Z   ssl-default-bind-ciphers ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:AES128-GCM-SHA256:AES128-SHA256:AES128-SHA:AES256-GCM-SHA384:AES256-SHA256:AES256-SHA:DHE-DSS-AES128-SHA:DES-CBC3-SHA
[haproxy-1]2017-02-17T22:03:17.142235163Z defaults
[haproxy-1]2017-02-17T22:03:17.142245940Z   balance roundrobin
[haproxy-1]2017-02-17T22:03:17.142256416Z   log global
[haproxy-1]2017-02-17T22:03:17.142267093Z   mode http
[haproxy-1]2017-02-17T22:03:17.142277720Z   option redispatch
[haproxy-1]2017-02-17T22:03:17.142288213Z   option httplog
[haproxy-1]2017-02-17T22:03:17.142298583Z   option dontlognull
[haproxy-1]2017-02-17T22:03:17.142309020Z   option forwardfor
[haproxy-1]2017-02-17T22:03:17.142319410Z   timeout connect 5000
[haproxy-1]2017-02-17T22:03:17.142329856Z   timeout client 50000
[haproxy-1]2017-02-17T22:03:17.142340166Z   timeout server 50000
[haproxy-1]2017-02-17T22:03:17.142350500Z listen stats
[haproxy-1]2017-02-17T22:03:17.142361160Z   bind :1936
[haproxy-1]2017-02-17T22:03:17.142371570Z   mode http
[haproxy-1]2017-02-17T22:03:17.142382053Z   stats enable
[haproxy-1]2017-02-17T22:03:17.142392440Z   timeout connect 10s
[haproxy-1]2017-02-17T22:03:17.142403003Z   timeout client 1m
[haproxy-1]2017-02-17T22:03:17.142413460Z   timeout server 1m
[haproxy-1]2017-02-17T22:03:17.142423906Z   stats hide-version
[haproxy-1]2017-02-17T22:03:17.142434476Z   stats realm Haproxy\ Statistics
[haproxy-1]2017-02-17T22:03:17.142445523Z   stats uri /
[haproxy-1]2017-02-17T22:03:17.142455893Z   stats auth stats:stats
[haproxy-1]2017-02-17T22:03:17.142466210Z frontend default_port_80
[haproxy-1]2017-02-17T22:03:17.142476510Z   bind :80
[haproxy-1]2017-02-17T22:03:17.142486763Z   reqadd X-Forwarded-Proto:\ http
[haproxy-1]2017-02-17T22:03:17.142497323Z   maxconn 4096
[haproxy-1]2017-02-17T22:03:17.142507683Z   default_backend default_service
[haproxy-1]2017-02-17T22:03:17.142518060Z backend default_service
[haproxy-1]2017-02-17T22:03:17.142528563Z   server HELLO_1 10.7.0.2:80 check inter 2000 rise 2 fall 3
[haproxy-1]2017-02-17T22:03:17.142539203Z INFO:haproxy:Reloading HAProxy
[haproxy-1]2017-02-17T22:03:17.163581588Z INFO:haproxy:HAProxy has been reloaded(PID: 15)
[haproxy-1]2017-02-17T22:03:17.164230369Z INFO:haproxy:===========END===========
[haproxy-1]2017-02-17T22:03:17.176606924Z INFO:haproxy:HAProxy(PID:14) has been terminated```

kevinsmith commented 7 years ago

Yep, I'm seeing the same thing you're seeing on Digital Ocean. Wasn't able to reproduce the problem there no matter the configuration.

I was able to reproduce this on Azure, however, with a relatively straightforward configuration. Here are the steps:

Use Docker Cloud to set up a new STANDARD_DS1 node on Azure. (Mine is in the eastus2 region, fwiw.) Use Docker Cloud to set up this node, not BYON.

Deploy this stack:

lb:
image: 'dockercloud/haproxy:latest'
links:
- web-green
ports:
- '80:80'
roles:
- global
web-blue:
image: 'dockercloud/hello-world:latest'
target_num_containers: 2
web-green:
image: 'dockercloud/hello-world:latest'
target_num_containers: 2

Switch links immediately to web-blue. It should work.

Wait 5 minutes. Switch links to web-green. It will get stuck at:

INFO:haproxy:=> Add task: Docker Cloud Event: New action is executed on the Haproxy container
INFO:haproxy:=> Executing task: Docker Cloud Event: New action is executed on the Haproxy container

dev-lusaja commented 7 years ago

I make a bash hook for listen docker events and reload the balancer...

See this example code https://github.com/dev-lusaja/Docker-Cloud-HAproxy/tree/master/Compose-v2

tifayuki commented 7 years ago

@kevinsmith yes, confirmed that it happens on azure consistently. The code that hangs for 15 mins is here: https://github.com/docker/python-dockercloud/blob/4325c7c68b5751bbba85e7c3d33596796a4dc4c2/dockercloud/api/http.py#L58

I tested both requests 2.7.0(the one that haproxy is using at the moment and 2.13.0(latest version) with the following code, and the send method always hangs after inactive for 5 mins:

>>> import requests
>>>
>>> s=requests.Session()
>>> req=requests.Request("GET", "https://cloud.docker.com/api/app/v1/tifayuki/container/0eb97404-d7d9-405e-a862-2b925e41be07/", headers={'Content-Type': 'application/json', 'Authorization': 'Basic basic_auth'})
>>>
>>> r=s.prepare_request(req)
>>> s.send(r, timeout=10)
<Response [200]>
>>> import time
>>> time.sleep(300)
>>> s.send(r, timeout=10)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/docker/.local/lib/python2.7/site-packages/requests/sessions.py", line 609, in send
    r = adapter.send(request, **kwargs)
  File "/home/docker/.local/lib/python2.7/site-packages/requests/adapters.py", line 499, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='cloud.docker.com', port=443): Read timed out. (read timeout=10)
>>> s.send(r, timeout=10)
<Response [200]>

Adding time timeout will definitely help with the issue, and haproxy will retry on the failure here: https://github.com/docker/dockercloud-haproxy/blob/master/haproxy/utils.py#L18

The issue will be fixed in our python SDK, and will be applied to the repo the next release.

kevinsmith commented 7 years ago

This is great news! Thanks so much for digging in to this.

Any idea why this seems to be specific to the Azure environment?

evandervalk commented 7 years ago

I've seen the same issue happen as well. Only on the Azure environment did it not automatically reconfigure itself. I'll be looking forward to the fix.

kevinsmith commented 7 years ago

I just noticed that HAProxy is now picking up changes and reloading without requiring a redeploy, as before, and I haven't changed anything about our hosting or docker setup. There's really nothing else to report, but I wanted to make a note of it incase anyone knows of something changing elsewhere that made this happen.

tifayuki commented 7 years ago

@kevinsmith

I don't think anything is changed so far.

I have updated the dockercloud python SDK to allow setting a timeout(15seconds) for the API call. The change is in staging branch and will be published soon.

cs278 commented 6 years ago

I'm also experiencing this issue when running on Docker Cloud, it seems to work as indented if you edit the service directly but if you update a stack (which in turn updates the service) then the events do not get processed. Perhaps this is why some people see the issue whereas others don't.

I've run with DEBUG=1 and confirmed the events are received on the WebSocket in both cases but when using a stack file they do not seem to contain the required parent service URI which causes this line not to match.

Running /reload.sh inside the container is enough to get the configuration changes to apply.

docker-archive / dockercloud-haproxy

Changes need to redeploy to take effect #102