Patroni: crush

Created on 18 Oct 2019 · 8Comments · Source: zalando/patroni

Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,882 WARNING: Exception happened during processing of request from 10.x.x.10:49050
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,890 WARNING: Exception happened during processing of request from 10.x.x.10:49056
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,893 ERROR:
Oct 18 22:03:02 Project-db1 patroni[534]: Traceback (most recent call last):
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 339, in wrapper
Oct 18 22:03:02 Project-db1 patroni[534]:     retval = func(self, *args, **kwargs) is not None
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 538, in _update_leader
Oct 18 22:03:02 Project-db1 patroni[534]:     return self.retry(self._client.test_and_set, self.leader_path, self._name, self._name, self._ttl)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 323, in retry
Oct 18 22:03:02 Project-db1 patroni[534]:     return self._retry.copy()(*args, **kwargs)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/utils.py", line 313, in __call__
Oct 18 22:03:02 Project-db1 patroni[534]:     return func(*args, **kwargs)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 703, in test_and_set
Oct 18 22:03:02 Project-db1 patroni[534]:     return self.write(key, value, prevValue=prev_value, ttl=ttl)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 500, in write
Oct 18 22:03:02 Project-db1 patroni[534]:     response = self.api_execute(path, method, params=params)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 218, in api_execute
Oct 18 22:03:02 Project-db1 patroni[534]:     return self._handle_server_response(response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 987, in _handle_server_response
Oct 18 22:03:02 Project-db1 patroni[534]:     etcd.EtcdError.handle(r)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/etcd/__init__.py", line 306, in handle
Oct 18 22:03:02 Project-db1 patroni[534]:     raise exc(msg, payload)
Oct 18 22:03:02 Project-db1 patroni[534]: etcd.EtcdCompareFailed: Compare failed : [n32-Project-db1 != m9-Project-db2]
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,897 WARNING: Exception happened during processing of request from 10.x.x.66:45956
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,900 WARNING: Traceback (most recent call last):
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
Oct 18 22:03:02 Project-db1 patroni[534]:     self.finish_request(request, client_address)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
Oct 18 22:03:02 Project-db1 patroni[534]:     self.RequestHandlerClass(request, client_address, self)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 426, in handle
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle_one_request()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 414, in handle_one_request
Oct 18 22:03:02 Project-db1 patroni[534]:     method()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 129, in do_GET
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_status_response(status_code, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 85, in _write_status_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_json_response(status_code, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 50, in _write_json_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_response(status_code, json.dumps(response), content_type='application/json')
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 47, in _write_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self.wfile.write(body.encode('utf-8'))
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 799, in write
Oct 18 22:03:02 Project-db1 patroni[534]:     self._sock.sendall(b)
Oct 18 22:03:02 Project-db1 patroni[534]: BrokenPipeError: [Errno 32] Broken pipe
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,900 WARNING: Traceback (most recent call last):
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
Oct 18 22:03:02 Project-db1 patroni[534]:     self.finish_request(request, client_address)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
Oct 18 22:03:02 Project-db1 patroni[534]:     self.RequestHandlerClass(request, client_address, self)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 426, in handle
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle_one_request()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 414, in handle_one_request
Oct 18 22:03:02 Project-db1 patroni[534]:     method()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 129, in do_GET
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_status_response(status_code, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 85, in _write_status_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_json_response(status_code, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 50, in _write_json_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_response(status_code, json.dumps(response), content_type='application/json')
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 47, in _write_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self.wfile.write(body.encode('utf-8'))
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 799, in write
Oct 18 22:03:02 Project-db1 patroni[534]:     self._sock.sendall(b)
Oct 18 22:03:02 Project-db1 patroni[534]: BrokenPipeError: [Errno 32] Broken pipe
Oct 18 22:03:02 Project-db1 patroni[534]: 2019-10-18 22:03:02,904 WARNING: Traceback (most recent call last):
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
Oct 18 22:03:02 Project-db1 patroni[534]:     self.finish_request(request, client_address)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
Oct 18 22:03:02 Project-db1 patroni[534]:     self.RequestHandlerClass(request, client_address, self)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 426, in handle
Oct 18 22:03:02 Project-db1 patroni[534]:     self.handle_one_request()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/http/server.py", line 414, in handle_one_request
Oct 18 22:03:02 Project-db1 patroni[534]:     method()
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 140, in do_GET_patroni
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_status_response(200, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 85, in _write_status_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_json_response(status_code, response)
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 50, in _write_json_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self._write_response(status_code, json.dumps(response), content_type='application/json')
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 47, in _write_response
Oct 18 22:03:02 Project-db1 patroni[534]:     self.wfile.write(body.encode('utf-8'))
Oct 18 22:03:02 Project-db1 patroni[534]:   File "/usr/lib/python3.7/socketserver.py", line 799, in write
Oct 18 22:03:02 Project-db1 patroni[534]:     self._sock.sendall(b)
Oct 18 22:03:02 Project-db1 patroni[534]: BrokenPipeError: [Errno 32] Broken pipe

10.x.x.10 - This is local ip, 10.x.x.10:49050 i think this is curl("curl --fail --verbose --max-time 2 http://10.10.16.10:8008/"). It runs every 2 sec, to monitor status primary/standby.
10.x.x.66 - This is ip from second postgresql server

There was uptime about 1 month, and suddenly this crush.

ii postgresql-10 10.10-1.pgdg100+1 amd64
ii patroni 1.6.0-2.pgdg100+1 all
ii etcd 3.2.26+dfsg-3 all

Source

oleg9301

Most helpful comment

When you make ttl too small you increase a chance of false positives. System becomes more critical to a good network and so on. I would personally never make ttl smaller than 20 seconds. Sometimes we even increase it to 1 minute.

CyberDem0n on 19 Oct 2019

👍2

All 8 comments

Oct 18 22:03:02 Project-db1 patroni[534]: etcd.EtcdCompareFailed: Compare failed : [n32-Project-db1 != m9-Project-db2]

Apparently for some reason the node was frozen (maybe due to the high load) so the leader key expired. Therefore other node got the lock and promoted.

CyberDem0n on 18 Oct 2019

There was no highload(as i see in logs, and Zabbix).

logs from other node:

Oct 18 22:02:53 m9-Project-db2 patroni[553]: 2019-10-18 22:02:53,640 INFO: Selected new etcd server http://10.X.X.82:2379
Oct 18 22:02:53 m9-Project-db2 patroni[553]: 2019-10-18 22:02:53,645 INFO: does not have lock
Oct 18 22:02:57 m9-Project-db2 patroni[553]: 2019-10-18 22:02:57,640 INFO: Selected new etcd server http://10.X.X.66:2379
Oct 18 22:02:57 m9-Project-db2 patroni[553]: 2019-10-18 22:02:57,643 INFO: does not have lock
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01,604 WARNING: Request failed to n32-Project-db1: GET http://10.X.X.10:8008/patroni (HTTPConnectionPool(host='10.X.X.10', port=8008): Read timed out. (read timeout=2))
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01,710 INFO: promoted self to leader by acquiring session lock
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.725 MSK [5664] LOG:  received promote request
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.725 MSK [5672] FATAL:  terminating walreceiver process due to administrator command
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.727 MSK [5664] LOG:  record with incorrect prev-link 7D30/302E3239 at 189/8D17DD98
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.727 MSK [5664] LOG:  redo done at 189/8D17DD70
Oct 18 22:03:01 m9-Project-db2 patroni[553]: server promoting
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01,728 INFO: cleared rewind state after becoming the leader
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.732 MSK [5664] LOG:  selected new timeline ID: 42
Oct 18 22:03:01 m9-Project-db2 patroni[553]: 2019-10-18 22:03:01.809 MSK [5664] LOG:  archive recovery complete
Oct 18 22:03:02 m9-Project-db2 patroni[553]: 2019-10-18 22:03:02.151 MSK [5661] LOG:  database system is ready to accept connections

Maybe this is a network problem, between node2 -> node1

I'm confused with this:
GET http://10.X.X.10:8008/patroni (HTTPConnectionPool(host='10.X.X.10', port=8008): Read timed out. (read timeout=2))
Patroni waits only for 2 seconds and then change primary, without any retry and other timeout?

My bootstrap config

bootstrap:
  dcs:
    loop_wait: 4
    maximum_lag_on_failover: 1048576
    postgresql:
      use_pg_rewind: true
      use_slots: true
      parameters:
        max_connections: 200
        max_replication_slots: 10
    retry_timeout: 3
    ttl: 10

oleg9301 on 19 Oct 2019

CyberDem0n on 19 Oct 2019

👍2

The same cluster

Nov  3 21:18:30 NAME-db1 patroni[17196]: Traceback (most recent call last):
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 339, in wrapper
Nov  3 21:18:30 NAME-db1 patroni[17196]:     retval = func(self, *args, **kwargs) is not None
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 538, in _update_leader
Nov  3 21:18:30 NAME-db1 patroni[17196]:     return self.retry(self._client.test_and_set, self.leader_path, self._name, self._name, self._ttl)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 323, in retry
Nov  3 21:18:30 NAME-db1 patroni[17196]:     return self._retry.copy()(*args, **kwargs)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/utils.py", line 313, in __call__
Nov  3 21:18:30 NAME-db1 patroni[17196]:     return func(*args, **kwargs)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 703, in test_and_set
Nov  3 21:18:30 NAME-db1 patroni[17196]:     return self.write(key, value, prevValue=prev_value, ttl=ttl)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 500, in write
Nov  3 21:18:30 NAME-db1 patroni[17196]:     response = self.api_execute(path, method, params=params)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/dcs/etcd.py", line 218, in api_execute
Nov  3 21:18:30 NAME-db1 patroni[17196]:     return self._handle_server_response(response)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/etcd/client.py", line 987, in _handle_server_response
Nov  3 21:18:30 NAME-db1 patroni[17196]:     etcd.EtcdError.handle(r)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/etcd/__init__.py", line 306, in handle
Nov  3 21:18:30 NAME-db1 patroni[17196]:     raise exc(msg, payload)
Nov  3 21:18:30 NAME-db1 patroni[17196]: etcd.EtcdKeyNotFound: Key not found : /db/NAME/leader
Nov  3 21:18:30 NAME-db1 patroni[17196]: 2019-11-03 21:18:30,769 WARNING: Exception happened during processing of request from 10.x.x.x:47084
Nov  3 21:18:30 NAME-db1 patroni[17196]: 2019-11-03 21:18:30,771 WARNING: Traceback (most recent call last):
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self.finish_request(request, client_address)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self.RequestHandlerClass(request, client_address, self)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self.handle()
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/http/server.py", line 426, in handle
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self.handle_one_request()
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/http/server.py", line 414, in handle_one_request
Nov  3 21:18:30 NAME-db1 patroni[17196]:     method()
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 129, in do_GET
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self._write_status_response(status_code, response)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 85, in _write_status_response
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self._write_json_response(status_code, response)
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 50, in _write_json_response
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self._write_response(status_code, json.dumps(response), content_type='application/json')
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3/dist-packages/patroni/api.py", line 47, in _write_response
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self.wfile.write(body.encode('utf-8'))
Nov  3 21:18:30 NAME-db1 patroni[17196]:   File "/usr/lib/python3.7/socketserver.py", line 799, in write
Nov  3 21:18:30 NAME-db1 patroni[17196]:     self._sock.sendall(b)
Nov  3 21:18:30 NAME-db1 patroni[17196]: BrokenPipeError: [Errno 32] Broken pipe
Nov  3 21:18:30 NAME-db1 patroni[17196]: 2019-11-03 21:18:30,769 ERROR: failed to update leader lock
Nov  3 21:18:30 NAME-db1 patroni[17196]: 2019-11-03 21:18:30.801 MSK [23865] LOG:  received immediate shutdown request

oleg9301 on 3 Nov 2019

i have 10 prod clusters more, and no problem with them.
But i have 1 difference, on this problematic cluster I use debian 10.
Software patroni/etcd/postgresql I use the same version on every cluster.
ii postgresql-10 10.10-1.pgdg100+1 amd64
ii patroni 1.6.0-2.pgdg100+1 all
ii etcd 3.2.26+dfsg-3 all

oleg9301 on 3 Nov 2019

Debian 10...
I think you are hitting the memory leak issue: https://github.com/zalando/patroni/pull/1200

CyberDem0n on 3 Nov 2019

Yeah
Python 3.7.3 (default, Apr 3 2019, 05:39:12)
Vs debian 9
Python 3.5.3 (default, Sep 27 2018, 17:25:39)

Can I just add one string in patroni/api.py for version 1.6.0?(like in commit ba7ae49c1dc696c84e095409e073952adf5e46f4)
daemon_threads = True

oleg9301 on 3 Nov 2019

Yes, that one line fix should help

CyberDem0n on 3 Nov 2019

👍1

Was this page helpful?

0 / 5 - 0 ratings