Add configuration option to suppress duplicate heartbeat logs (#3252)

Close #3251

docs/ENVIRONMENT.rst

@@ -32,6 +32,10 @@ Log
 -  **PATRONI\_LOG\_FILE\_NUM**: The number of application logs to retain.
 -  **PATRONI\_LOG\_FILE\_SIZE**: Size of patroni.log file (in bytes) that triggers a log rolling.
 -  **PATRONI\_LOG\_LOGGERS**: Redefine logging level per python module. Example ``PATRONI_LOG_LOGGERS="{patroni.postmaster: WARNING, urllib3: DEBUG}"``
+-  **PATRONI\_LOG\_DEDUPLICATE\_HEARTBEAT\_LOGS**: If set to ``true``, successive heartbeat logs that are identical shall not be output. Default value is ``false``.
+
+.. warning::
+   The time the HA loop executes at can be very valuable information in diagnosing failovers due to resource exhaustion and similar problems. When ``PATRONI_LOG_DEDUPLICATE_HEARTBEAT_LOGS`` is set to ``true`` there will be no log generated for the HA loop execution (unless the leader changes) and hence this potentially useful information will not be available from the logs.
 
 Citus
 -----

docs/yaml_configuration.rst

@@ -36,6 +36,10 @@ Log
 
    -  **patroni.postmaster: WARNING**
    -  **urllib3: DEBUG**
+-  **deduplicate_heartbeat_logs**: If set to ``true``, successive heartbeat logs that are identical shall not be output. Default value is ``false``.
+
+.. warning::
+   The time the HA loop executes at can be very valuable information in diagnosing failovers due to resource exhaustion and similar problems. When ``deduplicate_heartbeat_logs`` is set to ``true`` there will be no log generated for the HA loop execution (unless the leader changes) and hence this potentially useful information will not be available from the logs.
 
 Here is an example of how to config patroni to log in json format.
 

patroni/config.py

@@ -541,7 +541,8 @@ class Config(object):
         _set_section_values('postgresql', ['listen', 'connect_address', 'proxy_address',
                                            'config_dir', 'data_dir', 'pgpass', 'bin_dir'])
         _set_section_values('log', ['type', 'level', 'traceback_level', 'format', 'dateformat', 'static_fields',
-                                    'max_queue_size', 'dir', 'mode', 'file_size', 'file_num', 'loggers'])
+                                    'max_queue_size', 'dir', 'mode', 'file_size', 'file_num', 'loggers',
+                                    'deduplicate_heartbeat_logs'])
         _set_section_values('raft', ['data_dir', 'self_addr', 'partner_addrs', 'password', 'bind_addr'])
 
         for binary in ('pg_ctl', 'initdb', 'pg_controldata', 'pg_basebackup', 'postgres', 'pg_isready', 'pg_rewind'):
@@ -550,7 +551,8 @@ class Config(object):
                 ret['postgresql'].setdefault('bin_name', {})[binary] = value
 
         # parse all values retrieved from the environment as Python objects, according to the expected type
-        for first, second in (('restapi', 'allowlist_include_members'), ('ctl', 'insecure')):
+        for first, second in (('restapi', 'allowlist_include_members'), ('ctl', 'insecure'),
+                              ('log', 'deduplicate_heartbeat_logs')):
             value = ret.get(first, {}).pop(second, None)
             if value:
                 value = parse_bool(value)

patroni/log.py

@@ -517,6 +517,7 @@ class PatroniLogger(Thread):
             self._root_logger.removeHandler(self._proxy_handler)
 
         prev_record = None
+        prev_hb_msg = ''
 
         while True:
             self._close_old_handlers()
@@ -535,8 +536,16 @@ class PatroniLogger(Thread):
                     prev_record, record = record, None
                 else:
                     if prev_record and prev_record.thread == record.thread:
-                        if not (record.msg.startswith('no action. ') or record.msg.startswith('PAUSE: no action')):
+                        if self._is_heartbeat_msg(record):
+                            config = self._config or {}
+                            deduplicate_heartbeat_logs = config.get('deduplicate_heartbeat_logs', False)
+                            if record.msg == prev_hb_msg and deduplicate_heartbeat_logs:
+                                record = None
+                            else:
+                                prev_hb_msg = record.msg
+                        else:
                             self.log_handler.handle(prev_record)
+                            prev_hb_msg = None
                         prev_record = None
 
             if record:
@@ -544,6 +553,16 @@ class PatroniLogger(Thread):
 
             self._queue_handler.queue.task_done()
 
+    @staticmethod
+    def _is_heartbeat_msg(record: logging.LogRecord) -> bool:
+        """Checks if the given record contains a heartbeat message.
+
+        :param record: the record to check.
+
+        :returns: ``True`` if the record contains a heartbeat message, ``False`` otherwise.
+        """
+        return record.msg.startswith('no action. ') or record.msg.startswith('PAUSE: no action')
+
     def shutdown(self) -> None:
         """Shut down the logger thread."""
         try:

patroni/validator.py

@@ -1001,7 +1001,8 @@ schema = Schema({
         Optional("file_num"): int,
         Optional("file_size"): int,
         Optional("mode"): IntValidator(min=0, max=511, expected_type=int, raise_assert=True),
-        Optional("loggers"): dict
+        Optional("loggers"): dict,
+        Optional("deduplicate_heartbeat_logs"): bool
     },
     Optional("ctl"): {
         Optional("insecure"): bool,

tests/test_log.py

@@ -93,6 +93,17 @@ class TestPatroniLogger(unittest.TestCase):
         logger.shutdown()
         self.assertEqual(logger.records_lost, 0)
 
+    def test_deduplicate_heartbeat_logs(self):
+        logger = PatroniLogger()
+        logger.reload_config({'level': 'INFO', 'deduplicate_heartbeat_logs': True})
+        logger.start()
+        _LOG.info('Lock owner: ')
+        _LOG.info('no action. I am (patroni2), a secondary, and following a leader (patroni3)')
+        _LOG.info('Lock owner: ')
+        _LOG.info('no action. I am (patroni2), a secondary, and following a leader (patroni3)')
+        logger.shutdown()
+        self.assertEqual(logger.records_lost, 0)
+
     def test_json_list_format(self):
         config = {
             'type': 'json',