From c97ad83396c192e43137ba8538e8c9727ce808cd Mon Sep 17 00:00:00 2001 From: Michael Morris <105736419+MichaelMorrisEst@users.noreply.github.com> Date: Tue, 4 Feb 2025 15:25:08 +0000 Subject: [PATCH] Add configuration option to suppress duplicate heartbeat logs (#3252) Close #3251 --- docs/ENVIRONMENT.rst | 4 ++++ docs/yaml_configuration.rst | 4 ++++ patroni/config.py | 6 ++++-- patroni/log.py | 21 ++++++++++++++++++++- patroni/validator.py | 3 ++- tests/test_log.py | 11 +++++++++++ 6 files changed, 45 insertions(+), 4 deletions(-) diff --git a/docs/ENVIRONMENT.rst b/docs/ENVIRONMENT.rst index b6c6fe01..05a8dd26 100644 --- a/docs/ENVIRONMENT.rst +++ b/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 ----- diff --git a/docs/yaml_configuration.rst b/docs/yaml_configuration.rst index be3852c8..1e2aa457 100644 --- a/docs/yaml_configuration.rst +++ b/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. diff --git a/patroni/config.py b/patroni/config.py index 45d2391f..048c5bbf 100644 --- a/patroni/config.py +++ b/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) diff --git a/patroni/log.py b/patroni/log.py index d37024ae..0bf61e1d 100644 --- a/patroni/log.py +++ b/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: diff --git a/patroni/validator.py b/patroni/validator.py index ae924c2b..5416b51a 100644 --- a/patroni/validator.py +++ b/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, diff --git a/tests/test_log.py b/tests/test_log.py index 98d7d625..dbc4ec19 100644 --- a/tests/test_log.py +++ b/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',