Patroni: Messages at wrong priority flooding log

[phemmer]

Describe the bug
Patroni is very spammy in the logs, and drowns out meaningful information.

For example my logs have this:

Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:42 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: no action.  i am the leader with the lock
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911
Oct 09 21:38:43 ded18911 patroni[23453]: INFO: Lock owner: ded18911; I am ded18911

As you can see, that's 24 lines every second. These messages should be logged at level DEBUG, not INFO.

With it as it is, any meaningful messages that show up are quickly lost as they're flooded out.

To Reproduce
Steps to reproduce the behavior:
Start patroni with default setting for log level.

Expected behavior
Patroni should be quiet unless it has something meaningful to say.

Environment

• Patroni version: 2.0.1
• PostgreSQL version: 12.4
• DCS (and its version): Raft

Patroni configuration file

log:
  level: INFO
  format: '%(levelname)s: %(message)s'
raft:
  self_addr: 192.168.122.78:2222
  partner_addrs:
    - 192.168.122.163:2222
    - 192.168.122.78:2222
  data_dir: /var/lib/postgresql/12/main-patroni
restapi:
  listen: 127.0.0.1:8008
  connect_address: 127.0.0.1:8008
bootstrap:
  dcs: {}
postgresql:
  listen: 0.0.0.0:5432
  connect_address: 192.168.122.78:5432
  config_dir: /etc/postgresql/12/main
  pgpass: /etc/postgresql/12/main/pgpass
  data_dir: /var/lib/postgresql/12/main
  bin_dir: /usr/lib/postgresql/12/bin
  use_pg_rewind: true
  use_unix_socket: true
  authentication:
    replication:
      username: replicator
      password: abcd1234
    rewind:
      username: rewind
      password: abcd1234

Have you checked Patroni logs?
Yes. Very spammy. See above.

Have you checked PostgreSQL logs?
They pop in now and then, and are quickly flooded off the screen.

Have you tried to use GitHub issue search?
Didn't see anything.

Additional context

[CyberDem0n]

Is there a reason to not follow the issue template checklist? Specifically patronictl show-config. It is there for a purpose!

Now I have to guess that you set loop_wait, retry_timeout, and ttl to ridiculously low value hoping to get a sub-second automatic failover. That doesn't work like this, you can't beat laws of physics!

Also, looking at your config (values of restapi.connect_address and restapi.listen), I can tell for sure that you never read the documentation: https://patroni.readthedocs.io/en/latest/SETTINGS.html#rest-api

[phemmer]

Wow. You need to ditch the attitude.

[CyberDem0n]

There are very good reasons to have the issue template and all very specific questions in it, because It helps to avoid unnecessary ping-pongs and identify problems.
You come for help, don't provide all required information and now start telling about an attitude?

[phemmer]

Yes, because your attitude has now caused a new problem.
Instead of asking normally, you make incorrect assumptions and attack the other person. Now here we are completely ignoring the issue at hand. And the issue is now being prolonged because I'm going to wait for someone else rather than deal with you, which is likely to continue to be unproductive and combative.

[CyberDem0n]

Wrong assumptions?

The only way to get so many log lines per second is by setting loop_wait to the value that is very close to 0. People doing so in hopes to reduce the failover time, what in fact is useless and only producing unnecessary load.

Also documentation explicitly tells that the restapi.connect_address should not be set to localhost, but your config contains it anyway. API is used to check the health of other nodes in the cluster during the leader race and by setting it localhost every node connects to itself instead of others. With such a config automatic failover is broken.