Reverse proxying hits occasional upstream connections refused

[jefferai]

I would like to put etcd behind a reverse proxy so that I can more easily control authentication and authorization. The heartbeats come in regularly but every now and again etcd refuses the connection. This is running etcd b4e4bf4.

Normally I see expected access log entries, many per second.

10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:17 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"
10.8.8.105 - - [20/May/2014:17:41:18 +0000] "POST /log/append HTTP/1.1" 200 23 "-" "Go 1.1 package http"

However, fairly regularly (every 11 seconds with occasional deviances) I get errors:

2014/05/20 17:39:49 [error] 11348#0: *9606 connect() failed (111: Connection refused) while connecting to upstream, client: 10.8.8.105, server: , request: "POST /log/append HTTP/1.1", upstream: "http://[::1]:7001/log/append", host: "10.8.8.108:7001"
2014/05/20 17:39:51 [error] 11347#0: *9708 connect() failed (111: Connection refused) while connecting to upstream, client: 10.8.8.105, server: , request: "POST /log/append HTTP/1.1", upstream: "http://[::1]:7001/log/append", host: "10.8.8.108:7001"
2014/05/20 17:40:00 [error] 11348#0: *9810 connect() failed (111: Connection refused) while connecting to upstream, client: 10.8.8.105, server: , request: "POST /log/append HTTP/1.1", upstream: "http://[::1]:7001/log/append", host: "10.8.8.108:7001"
2014/05/20 17:40:11 [error] 11348#0: *10013 connect() failed (111: Connection refused) while connecting to upstream, client: 10.8.8.105, server: , request: "POST /log/append HTTP/1.1", upstream: "http://[::1]:7001/log/append", host: "10.8.8.108:7001"

I'm not sure that this is really affecting anything negatively, other than a dropped heartbeat now and again, but it's not clear why it should happen, either.

This is my nginx config; it's extremely basic.

server {
    listen 10.8.8.108:4001;

    access_log off;

    include proxy_params;

    location / {
        proxy_pass http://localhost:4001;
    }
}

server {
    listen 10.8.8.108:7001;

    access_log /var/log/nginx/etcd_server_access.log;

    include proxy_params;

    location / {
        allow 10.8.8.105;
        allow 10.8.8.107;
        deny all;
        proxy_pass http://localhost:7001;
    }
}

[yichengq]

Etcd should not reject the connection intentionally, but it has a time limit for single connection. If it exceeds that time, it will stop waiting.
Considering the heartbeat interval is 50ms, I think it may be reasonable to produce this log.

[jefferai]

I don't really understand your response. Are you suggesting that the issue is that the reverse proxy opens a connection to etcd and keeps it open, pipelining data; after the time limit is hit the connection drops and must be reopened?

Assuming this is the case, how do you explain the differing times between the drops?

[yichengq]

Nop.
Etcd has a timeout for each connection, and I think somewhere in the system (nginx? virtualbox?) causes some delay and fails the connection from time to time.
Could you try to set a larger heartbeat interval for the etcd?

[yichengq]

#960

[kelseyhightower]

@jefferai Sorry it's taken so long to get to this, but are you still having this issue? I've seen cases like this solved by tuning etcd -- check out the tuning guide: https://coreos.com/docs/cluster-management/debugging/etcd-tuning/

[jefferai]

Unsure. We stopped using etcd (and all software based on etcd) because of #815 . We will evaluate it again at some point when things have a chance to stabilize.

[kelseyhightower]

@jefferai Sorry to hear that, looks the #815 has been updated. I'm closing this out for now.