Patroni: Patroni not trying to reconnect to other etcd members

[bradnicholson]

I'm seeing a bit of an odd case under test that I can't quite explain. Wondering if you have any ideas.

This is with Patroni 1.3.6 with Python 2.7

We have a deployment with 2 Postgres Members and 3 etcd members deployed across three AZ's, lets call them AZ's X, Y, and Z

We have etcd's in each AZ, assume the name matches the AZ
etcdX
ectdY
etcdZ

and Postgres in two AZ's
pgX
pgY

All three etcd members are up and have formed a cluster by the time Patroni starts on both PG members. We have a connection to etcd hard coded to connect to etcdX on startup as such

etcd:
  host: <etcdX_IP>:4001

pgX becomes the master, pgY becomes a follower.

To test the failure, we fence off AZ X at the network layer from AZ's Y & Z.

pgX times out communicating with etcdX (presumably due to lack of quorum reads). It attempts to connect to etcdY and etcdZ and fails as expected. pgX goes read-only as expected.

pgY loses connectivity with etcdX. It does not try and reconnect to etcdY or etcdZ. It simply keeps retrying to connect to etcdX.

I'd expect that pgY should also be trying to reconnect to one of the other etcd members, but it does not. Any idea why?

We do plan on upgrading to the latest version and giving it the entire list of etcd hosts on startup, but I'm still interested in digging into this failure more.

[CyberDem0n]

pgY loses connectivity with etcdX. It does not try and reconnect to etcdY or etcdZ. It simply keeps retrying to connect to etcdX.

That's very strange. Up on start Patroni discovers topology of etcd cluster by performing request GET http://ip:4001/v2/machines. It should get in response three urls separated by comma (http://etcdX:4001,http://etcdY:4001,http://etcdZ:4001).
Can you verify that it really returns it?

In addition to that, to protect from the situation when all nodes except the current one were rotated with change of ip addresses, Patroni periodically (every 5 minutes) tries to rediscover etcd cluster topology (GET /v2/machines).

I'd expect that pgY should also be trying to reconnect to one of the other etcd members, but it does not. Any idea why?

It should try with other members. But for some reason it didn't got the right topology from etcd.

We do plan on upgrading to the latest version and giving it the entire list of etcd hosts on startup, but I'm still interested in digging into this failure more.

There are actually no changes in code which does discovery and reconnects in the latest version. Multiple hosts in the configuration would be used only for initial discovery of cluster topology.

I would recommend you to verify that all etcd nodes are returning the same cluster topology when you are executing following requests:

$ curl http://etcdX:4001/v2/members
$ curl http://etcdY:4001/v2/members
$ curl http://etcdZ:4001/v2/members

or something more advanced:

$ curl http://etcdX:4001/v2/machines
$ curl http://etcdY:4001/v2/machines
$ curl http://etcdZ:4001/v2/machines

Especially important to verify that whatever url's are returned from GET /machines are resolvable and accessible.

[mrquokka]

Also you can use replace "hosts" to "host" and print all your hosts on them. Used them week ago, with 2 patroni nodes and 2 etcd nodes.
Specifically in this case, i think that you also need to check etcd cluster configuration.

[bradnicholson]

Up on start Patroni discovers topology of etcd cluster by performing request GET http://ip:4001/v2/machines. It should get in response three urls separated by comma (http://etcdX:4001,http://etcdY:4001,http://etcdZ:4001).
Can you verify that it really returns it?

Confirmed. Both PG members return the correct list of etcd members.

I would recommend you to verify that all etcd nodes are returning the same cluster topology when you are executing following requests:

Confirmed that the etcd topology is correct and accessible. Checked the output of both /members and /machines from both PG members, all returned the correct members. I also hit the /health endpoint for all three members from each PG member, and all of them worked and reported the cluster was healthy.

Specifically in this case, i think that you also need to check etcd cluster configuration.

Cluster config is sound and cluster is healthy

Also you can use replace "hosts" to "host" and print all your hosts on them.

Does not make a difference. We are supplying IP addresses - not host names. They are routable and healthy (as per above)

I can reproduce the issue, and it seems to be transient.

If shut the network interface down on the etcd member we are connecting to - the problem happens. When I bring the interface backup, we reconnect to the same node and things start to work again. However, toggling up/down on etcd interface - it will eventually connected to another member

Here are the logs:

2018-02-20 14:30:21,962 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001
2018-02-20 14:30:25,298 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d81dd490>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-20 14:30:28,632 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d81dde90>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-20 14:30:31,969 ERROR: Failed to get list of machines from http://XX.XX.XX.XXX:4001/v2: MaxRetryError("HTTPConnectionPool(host='XX.XX.XX.XXX', port=4001): Max retries exceeded with url: /v2/machines (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d8e41210>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)'))",)
2018-02-20 14:30:31,970 ERROR: get_cluster
Traceback (most recent call last):
  File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 426, in _load_cluster
    result = self.retry(self._client.read, self.client_path(''), recursive=True)
  File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 313, in retry
    return self._retry.copy()(*args, **kwargs)
  File "/app/patroni-1.3.6/patroni/utils.py", line 259, in __call__
    return func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/etcd/client.py", line 597, in read
    timeout=timeout)
  File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 182, in api_execute
    self._load_machines_cache()
  File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 290, in _load_machines_cache
    self._machines_cache = self.machines
  File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 141, in machines
    raise etcd.EtcdException("Could not get the list of servers, "
EtcdException: Could not get the list of servers, maybe you provided the wrong host(s) to connect to?
2018-02-20 14:30:31,971 ERROR: Error communicating with DCS
2018-02-20 14:30:31,973 INFO: DCS is not accessible
2018-02-20 14:30:31,974 WARNING: Loop time exceeded, rescheduling immediately.
2018-02-20 14:30:31,974 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001
2018-02-20 14:30:35,310 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d8e41190>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-20 14:30:38,646 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d8e41390>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-20 14:30:41,982 ERROR: Failed to get list of machines from http://XX.XX.XX.XXX:4001/v2: MaxRetryError("HTTPConnectionPool(host='XX.XX.XX.XXX', port=4001): Max retries exceeded with url: /v2/machines (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fe6d8e41210>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)'))",)
2018-02-20 14:30:41,983 ERROR: Could not get the list of servers, maybe you provided the wrong host(s) to connect to?
2018-02-20 14:30:41,983 ERROR: Error communicating with DCS
2018-02-20 14:30:41,984 INFO: DCS is not accessible
2018-02-20 14:30:41,985 WARNING: Loop time exceeded, rescheduling immediately.
2018-02-20 14:30:41,985 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001

[bradnicholson]

I don't think it is actually transient. It's only after starting the network interface backup that it will select a new member to connect to (presumably Patroni can connect but the member is not back in the cluster).

[CyberDem0n]

Current logs are showing that Patroni's internal list of etcd nodes was exhausted and it returned back to the host specified in the configuration file. Since this host is not accessible, Patroni can't figure out where the other nodes are.

The question is why this internal list was exhausted? In order to answer it, I would like to see a logs starting from a few seconds before you have fenced AZ X from Y and Z.

Also it would be great if you change loglevel to DEBUG (https://github.com/zalando/patroni/blob/master/patroni/__init__.py#L138) and record a new logs.

P.S. Actually if you specify multiple hosts in the configuration file it will also help. Because it will use all of them when doing discovery of etcd cluster topology.

[bradnicholson]

With DEBUG log levels.

Startup - get's 3 members from the machine cache.

2018-02-21 12:50:49,264 DEBUG: New etcd client created for http://XX.XX.XX.XXX:4001
2018-02-21 12:50:49,264 DEBUG: Selection next machine in cache. Available machines: ['http://XX.XX.XX.XXX:4001']
2018-02-21 12:50:49,264 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001
2018-02-21 12:50:49,265 DEBUG: Converted retries value: 2 -> Retry(total=2, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:50:49,265 DEBUG: Starting new HTTP connection (1): XX.XX.XX.XXX
2018-02-21 12:50:49,269 DEBUG: http://XX.XX.XX.XXX:4001 "GET /v2/machines HTTP/1.1" 200 79
2018-02-21 12:50:49,269 DEBUG: Retrieved list of machines: [u'http://XX.XX.XX.XXX:4001', u'http://YY.YY.YYY.YYY:4001', u'http://ZZ.ZZ.ZZZ.ZZZ:4001']

Pre and post fence logs (fenced etcd member is running on XX.XX.XX.XXX)

2018-02-21 12:51:17,276 INFO: no action.  i am a secondary and i am following a leader
2018-02-21 12:51:17,276 DEBUG: About to wait on key /patroni/postgresql/leader, index 185
2018-02-21 12:51:17,276 DEBUG: Issuing read for key /patroni/postgresql/leader with args {'waitIndex': 185, 'recursive': None, 'timeout': 10.488511800765991, 'wait': True}
2018-02-21 12:51:17,277 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:17,279 DEBUG: http://XX.XX.XX.XXX:4001 "GET /v2/keys/patroni/postgresql/leader?waitIndex=185&wait=true HTTP/1.1" 200 None
2018-02-21 12:51:21,048 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:21] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:22,163 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:22] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:27,267 DEBUG: Issuing read for key /patroni/postgresql/ with args {'recursive': True}
2018-02-21 12:51:27,268 DEBUG: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:27,270 DEBUG: http://XX.XX.XX.XXX:4001 "GET /v2/keys/patroni/postgresql/?recursive=true HTTP/1.1" 200 1711
2018-02-21 12:51:27,271 INFO: Lock owner: pgX; I am pgY
2018-02-21 12:51:27,271 INFO: does not have lock
2018-02-21 12:51:27,272 DEBUG: Writing {"role":"replica","state":"running","conn_url":"postgres://AA.AA.AAA.AAA:5432/postgres","api_url":"http://AA.AA.AAA.AAA:8008/patroni","xlog_location":67109184} to key /patroni/postgresql/members/pgY ttl=30 dir=False append=False
2018-02-21 12:51:27,272 DEBUG: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:27,276 DEBUG: http://XX.XX.XX.XXX:4001 "PUT /v2/keys/patroni/postgresql/members/pgY HTTP/1.1" 200 711
2018-02-21 12:51:27,277 INFO: no action.  i am a secondary and i am following a leader
2018-02-21 12:51:27,277 DEBUG: About to wait on key /patroni/postgresql/leader, index 188
2018-02-21 12:51:27,277 DEBUG: Issuing read for key /patroni/postgresql/leader with args {'waitIndex': 188, 'recursive': None, 'timeout': 10.490375995635986, 'wait': True}
2018-02-21 12:51:27,277 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:27,279 DEBUG: http://XX.XX.XX.XXX:4001 "GET /v2/keys/patroni/postgresql/leader?waitIndex=188&wait=true HTTP/1.1" 200 None
2018-02-21 12:51:31,063 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:31] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:32,179 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:32] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:37,778 DEBUG: Watch timed out.
2018-02-21 12:51:37,778 DEBUG: Issuing read for key /patroni/postgresql/ with args {'recursive': True}
2018-02-21 12:51:37,778 DEBUG: Selection next machine in cache. Available machines: ['http://XX.XX.XX.XXX:4001']
2018-02-21 12:51:37,778 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001
2018-02-21 12:51:37,779 DEBUG: Converted retries value: 2 -> Retry(total=2, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:37,779 DEBUG: Starting new HTTP connection (1): XX.XX.XX.XXX
2018-02-21 12:51:41,115 DEBUG: Incremented Retry for (url='/v2/machines'): Retry(total=1, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:41,115 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d0a8510>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-21 12:51:41,115 DEBUG: Starting new HTTP connection (2): XX.XX.XX.XXX
2018-02-21 12:51:44,451 DEBUG: Incremented Retry for (url='/v2/machines'): Retry(total=0, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:44,452 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d0a8ed0>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-21 12:51:44,452 DEBUG: Starting new HTTP connection (3): XX.XX.XX.XXX
2018-02-21 12:51:47,787 ERROR: Failed to get list of machines from http://XX.XX.XX.XXX:4001/v2: MaxRetryError("HTTPConnectionPool(host='XX.XX.XX.XXX', port=4001): Max retries exceeded with url: /v2/machines (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d40d250>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)'))",)
2018-02-21 12:51:47,787 ERROR: get_cluster
 Traceback (most recent call last):
   File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 426, in _load_cluster
     result = self.retry(self._client.read, self.client_path(''), recursive=True)
   File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 313, in retry
     return self._retry.copy()(*args, **kwargs)
   File "/app/patroni-1.3.6/patroni/utils.py", line 259, in __call__
     return func(*args, **kwargs)
   File "/usr/local/lib/python2.7/dist-packages/etcd/client.py", line 597, in read
     timeout=timeout)
   File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 182, in api_execute
     self._load_machines_cache()
   File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 290, in _load_machines_cache
     self._machines_cache = self.machines
   File "/app/patroni-1.3.6/patroni/dcs/etcd.py", line 141, in machines
     raise etcd.EtcdException("Could not get the list of servers, "
 EtcdException: Could not get the list of servers, maybe you provided the wrong host(s) to connect to?
2018-02-21 12:51:47,788 ERROR: Error communicating with DCS
2018-02-21 12:51:47,788 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:47] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:47,789 DEBUG: API thread: AA.AA.AAA.AAA - - [21/Feb/2018 12:51:47] "GET / HTTP/1.1" 503 -
2018-02-21 12:51:47,790 INFO: DCS is not accessible
2018-02-21 12:51:47,791 WARNING: Loop time exceeded, rescheduling immediately.
2018-02-21 12:51:47,791 DEBUG: Issuing read for key /patroni/postgresql/ with args {'recursive': True}
2018-02-21 12:51:47,792 DEBUG: Selection next machine in cache. Available machines: ['http://XX.XX.XX.XXX:4001']
2018-02-21 12:51:47,792 INFO: Selected new etcd server http://XX.XX.XX.XXX:4001
2018-02-21 12:51:47,792 DEBUG: Converted retries value: 2 -> Retry(total=2, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:47,792 DEBUG: Starting new HTTP connection (4): XX.XX.XX.XXX
2018-02-21 12:51:51,128 DEBUG: Incremented Retry for (url='/v2/machines'): Retry(total=1, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:51,129 WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d40d1d0>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-21 12:51:51,129 DEBUG: Starting new HTTP connection (5): XX.XX.XX.XXX
2018-02-21 12:51:54,465 DEBUG: Incremented Retry for (url='/v2/machines'): Retry(total=0, connect=None, read=None, redirect=0, status=None)
2018-02-21 12:51:54,465 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0, status=None)) after connection broken by 'ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d0a8cd0>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)')': /v2/machines
2018-02-21 12:51:54,466 DEBUG: Starting new HTTP connection (6): XX.XX.XX.XXX
2018-02-21 12:51:57,802 ERROR: Failed to get list of machines from http://XX.XX.XX.XXX:4001/v2: MaxRetryError("HTTPConnectionPool(host='XX.XX.XX.XXX', port=4001): Max retries exceeded with url: /v2/machines (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7fd49d0a85d0>, 'Connection to XX.XX.XX.XXX timed out. (connect timeout=3.33333333333)'))",)
2018-02-21 12:51:57,803 ERROR: Could not get the list of servers, maybe you provided the wrong host(s) to connect to?
2018-02-21 12:51:57,803 ERROR: Error communicating with DCS

[CyberDem0n]

I think that I know what the problem is.

EtcdWatchTimedOut is a child of EtcdConnectionFailed. That mean when watch times out, it was also trying to rediscover etcd cluster topology.

Please try to test it with this fix: https://github.com/zalando/patroni/pull/630/files

[bradnicholson]

Confirmed - this fixes the issue. Thanks!

Can you see any issue with us back porting this fix to our 1.3.6 deployments prior to doing an upgrade? I tested it against 1.3.6, and presume it's fine - but worth asking.

[CyberDem0n]

Can you see any issue with us back porting this fix to our 1.3.6 deployments

I don't see any problem, there were not much changes in etcd code between 1.3.6 and master.