From f6943a859d007fba2d5328a1244cc22b315c3541 Mon Sep 17 00:00:00 2001 From: Polina Bungina <27892524+hughcapet@users.noreply.github.com> Date: Mon, 29 Jan 2024 10:44:25 +0100 Subject: [PATCH] Improve logging for Pg param change (#3008) * Convert old value to a human-readable format * Add log line about pg_controldata/global config mismatch that causes pending restart flag to be set --- patroni/postgresql/config.py | 19 ++-- patroni/utils.py | 196 +++++++++++++++++++++++++++++++---- tests/test_postgresql.py | 24 +++-- 3 files changed, 201 insertions(+), 38 deletions(-) diff --git a/patroni/postgresql/config.py b/patroni/postgresql/config.py index fd5edae70..51e83cf8f 100644 --- a/patroni/postgresql/config.py +++ b/patroni/postgresql/config.py @@ -17,7 +17,8 @@ from ..dcs import Leader, Member, RemoteMember, slot_name_from_member_name from ..exceptions import PatroniFatalException, PostgresConnectionException from ..file_perm import pg_perm -from ..utils import compare_values, parse_bool, parse_int, split_host_port, uri, validate_directory, is_subpath +from ..utils import (compare_values, maybe_convert_from_base_unit, parse_bool, parse_int, + split_host_port, uri, validate_directory, is_subpath) from ..validator import IntValidator, EnumValidator if TYPE_CHECKING: # pragma: no cover @@ -1102,27 +1103,29 @@ def reload_config(self, config: Dict[str, Any], sighup: bool = False) -> None: new_value = changes.pop(r[0]) if new_value is None or not compare_values(r[3], r[2], r[1], new_value): conf_changed = True + old_value = maybe_convert_from_base_unit(r[1], r[3], r[2]) if r[4] == 'postmaster': pending_restart = True - logger.info('Changed %s from %s to %s (restart might be required)', - r[0], r[1], new_value) + logger.info("Changed %s from '%s' to '%s' (restart might be required)", + r[0], old_value, new_value) if config.get('use_unix_socket') and r[0] == 'unix_socket_directories'\ or r[0] in ('listen_addresses', 'port'): local_connection_address_changed = True else: - logger.info('Changed %s from %s to %s', r[0], r[1], new_value) + logger.info("Changed %s from '%s' to '%s'", r[0], old_value, new_value) elif r[0] in self._server_parameters \ and not compare_values(r[3], r[2], r[1], self._server_parameters[r[0]]): # Check if any parameter was set back to the current pg_settings value # We can use pg_settings value here, as it is proved to be equal to new_value - logger.info('Changed %s from %s to %s', r[0], self._server_parameters[r[0]], r[1]) + logger.info("Changed %s from '%s' to '%s'", r[0], self._server_parameters[r[0]], new_value) conf_changed = True for param, value in changes.items(): if '.' in param: - # Check that user-defined-paramters have changed (parameters with period in name) + # Check that user-defined-parameters have changed (parameters with period in name) if value is None or param not in self._server_parameters \ or str(value) != str(self._server_parameters[param]): - logger.info('Changed %s from %s to %s', param, self._server_parameters.get(param), value) + logger.info("Changed %s from '%s' to '%s'", + param, self._server_parameters.get(param), value) conf_changed = True elif param in server_parameters: logger.warning('Removing invalid parameter `%s` from postgresql.parameters', param) @@ -1228,6 +1231,8 @@ def effective_configuration(self) -> CaseInsensitiveDict: cvalue = parse_int(data[cname]) if cvalue is not None and value is not None and cvalue > value: effective_configuration[name] = cvalue + logger.info("%s value in pg_controldata: %d, in the global configuration: %d." + " pg_controldata value will be used. Setting 'Pending restart' flag", name, cvalue, value) self._postgresql.set_pending_restart(True) # If we are using custom bootstrap with PITR it could fail when values like max_connections diff --git a/patroni/utils.py b/patroni/utils.py index 2b1ded5b8..f1da0dffe 100644 --- a/patroni/utils.py +++ b/patroni/utils.py @@ -10,6 +10,7 @@ :var WHITESPACE_RE: regular expression to match whitespace characters """ import errno +import itertools import logging import os import platform @@ -24,6 +25,7 @@ from typing import Any, Callable, Dict, Iterator, List, Optional, Union, Tuple, Type, TYPE_CHECKING +from collections import OrderedDict from dateutil import tz from json import JSONDecoder from urllib3.response import HTTPResponse @@ -46,6 +48,37 @@ WHITESPACE_RE = re.compile(r'[ \t\n\r]*', re.VERBOSE | re.MULTILINE | re.DOTALL) +def get_conversion_table(base_unit: str) -> Dict[str, Dict[str, Union[int, float]]]: + """Get conversion table for the specified base unit. + + If no conversion table exists for the passed unit, return an empty :class:`OrderedDict`. + + :param base_unit: unit to choose the conversion table for. + + :returns: :class:`OrderedDict` object. + """ + memory_unit_conversion_table: Dict[str, Dict[str, Union[int, float]]] = OrderedDict([ + ('TB', {'B': 1024**4, 'kB': 1024**3, 'MB': 1024**2}), + ('GB', {'B': 1024**3, 'kB': 1024**2, 'MB': 1024}), + ('MB', {'B': 1024**2, 'kB': 1024, 'MB': 1}), + ('kB', {'B': 1024, 'kB': 1, 'MB': 1024**-1}), + ('B', {'B': 1, 'kB': 1024**-1, 'MB': 1024**-2}) + ]) + time_unit_conversion_table: Dict[str, Dict[str, Union[int, float]]] = OrderedDict([ + ('d', {'ms': 1000 * 60**2 * 24, 's': 60**2 * 24, 'min': 60 * 24}), + ('h', {'ms': 1000 * 60**2, 's': 60**2, 'min': 60}), + ('min', {'ms': 1000 * 60, 's': 60, 'min': 1}), + ('s', {'ms': 1000, 's': 1, 'min': 60**-1}), + ('ms', {'ms': 1, 's': 1000**-1, 'min': 1 / (1000 * 60)}), + ('us', {'ms': 1000**-1, 's': 1000**-2, 'min': 1 / (1000**2 * 60)}) + ]) + if base_unit in ('B', 'kB', 'MB'): + return memory_unit_conversion_table + elif base_unit in ('ms', 's', 'min'): + return time_unit_conversion_table + return OrderedDict() + + def deep_compare(obj1: Dict[Any, Union[Any, Dict[Any, Any]]], obj2: Dict[Any, Union[Any, Dict[Any, Any]]]) -> bool: """Recursively compare two dictionaries to check if they are equal in terms of keys and values. @@ -272,33 +305,152 @@ def convert_to_base_unit(value: Union[int, float], unit: str, base_unit: Optiona >>> convert_to_base_unit(1, 'GB', '512 MB') is None True """ - convert: Dict[str, Dict[str, Union[int, float]]] = { - 'B': {'B': 1, 'kB': 1024, 'MB': 1024 * 1024, 'GB': 1024 * 1024 * 1024, 'TB': 1024 * 1024 * 1024 * 1024}, - 'kB': {'B': 1.0 / 1024, 'kB': 1, 'MB': 1024, 'GB': 1024 * 1024, 'TB': 1024 * 1024 * 1024}, - 'MB': {'B': 1.0 / (1024 * 1024), 'kB': 1.0 / 1024, 'MB': 1, 'GB': 1024, 'TB': 1024 * 1024}, - 'ms': {'us': 1.0 / 1000, 'ms': 1, 's': 1000, 'min': 1000 * 60, 'h': 1000 * 60 * 60, 'd': 1000 * 60 * 60 * 24}, - 's': {'us': 1.0 / (1000 * 1000), 'ms': 1.0 / 1000, 's': 1, 'min': 60, 'h': 60 * 60, 'd': 60 * 60 * 24}, - 'min': {'us': 1.0 / (1000 * 1000 * 60), 'ms': 1.0 / (1000 * 60), 's': 1.0 / 60, 'min': 1, 'h': 60, 'd': 60 * 24} - } + base_value, base_unit = strtol(base_unit, False) + if TYPE_CHECKING: # pragma: no cover + assert isinstance(base_value, int) - round_order = { - 'TB': 'GB', 'GB': 'MB', 'MB': 'kB', 'kB': 'B', - 'd': 'h', 'h': 'min', 'min': 's', 's': 'ms', 'ms': 'us' - } + convert_tbl = get_conversion_table(base_unit) + # {'TB': 'GB', 'GB': 'MB', ...} + round_order = dict(zip(convert_tbl, itertools.islice(convert_tbl, 1, None))) + if unit in convert_tbl and base_unit in convert_tbl[unit]: + value *= convert_tbl[unit][base_unit] / float(base_value) + if unit in round_order: + multiplier = convert_tbl[round_order[unit]][base_unit] + value = round(value / float(multiplier)) * multiplier + return value - if base_unit and base_unit not in convert: - base_value, base_unit = strtol(base_unit, False) - else: - base_value = 1 - if base_value is not None and base_unit in convert and unit in convert[base_unit]: - value *= convert[base_unit][unit] / float(base_value) +def convert_int_from_base_unit(base_value: int, base_unit: Optional[str]) -> Optional[str]: + """Convert an integer value in some base unit to a human-friendly unit. - if unit in round_order: - multiplier = convert[base_unit][round_order[unit]] - value = round(value / float(multiplier)) * multiplier + The output unit is chosen so that it's the greatest unit that can represent + the value without loss. - return value + :param base_value: value to be converted from a base unit + :param base_unit: unit of *value*. Should be one of the base units (case sensitive): + + * For space: ``B``, ``kB``, ``MB``; + * For time: ``ms``, ``s``, ``min``. + + :returns: :class:`str` value representing *base_value* converted from *base_unit* to the greatest + possible human-friendly unit, or ``None`` if conversion failed. + + :Example: + + >>> convert_int_from_base_unit(1024, 'kB') + '1MB' + + >>> convert_int_from_base_unit(1025, 'kB') + '1025kB' + + >>> convert_int_from_base_unit(4, '256MB') + '1GB' + + >>> convert_int_from_base_unit(4, '256 MB') is None + True + + >>> convert_int_from_base_unit(1024, 'KB') is None + True + """ + base_value_mult, base_unit = strtol(base_unit, False) + if TYPE_CHECKING: # pragma: no cover + assert isinstance(base_value_mult, int) + base_value *= base_value_mult + + convert_tbl = get_conversion_table(base_unit) + for unit in convert_tbl: + multiplier = convert_tbl[unit][base_unit] + if multiplier <= 1.0 or base_value % multiplier == 0: + return str(round(base_value / multiplier)) + unit + + +def convert_real_from_base_unit(base_value: float, base_unit: Optional[str]) -> Optional[str]: + """Convert an floating-point value in some base unit to a human-friendly unit. + + Same as :func:`convert_int_from_base_unit`, except we have to do the math a bit differently, + and there's a possibility that we don't find any exact divisor. + + :param base_value: value to be converted from a base unit + :param base_unit: unit of *value*. Should be one of the base units (case sensitive): + + * For space: ``B``, ``kB``, ``MB``; + * For time: ``ms``, ``s``, ``min``. + + :returns: :class:`str` value representing *base_value* converted from *base_unit* to the greatest + possible human-friendly unit, or ``None`` if conversion failed. + + :Example: + + >>> convert_real_from_base_unit(5, 'ms') + '5ms' + + >>> convert_real_from_base_unit(2.5, 'ms') + '2500us' + + >>> convert_real_from_base_unit(4.0, '256MB') + '1GB' + + >>> convert_real_from_base_unit(4.0, '256 MB') is None + True + """ + base_value_mult, base_unit = strtol(base_unit, False) + if TYPE_CHECKING: # pragma: no cover + assert isinstance(base_value_mult, int) + base_value *= base_value_mult + + result = None + convert_tbl = get_conversion_table(base_unit) + for unit in convert_tbl: + value = base_value / convert_tbl[unit][base_unit] + result = f'{value:g}{unit}' + if value > 0 and abs((round(value) / value) - 1.0) <= 1e-8: + break + return result + + +def maybe_convert_from_base_unit(base_value: str, vartype: str, base_unit: Optional[str]) -> str: + """Try to convert integer or real value in a base unit to a human-readable unit. + + Value is passed as a string. If parsing or subsequent conversion fails, the original + value is returned. + + :param base_value: value to be converted from a base unit. + :param vartype: the target type to parse *base_value* before converting (``integer`` + or ``real`` is expected, any other type results in return value being equal to the + *base_value* string). + :param base_unit: unit of *value*. Should be one of the base units (case sensitive): + + * For space: ``B``, ``kB``, ``MB``; + * For time: ``ms``, ``s``, ``min``. + + :returns: :class:`str` value representing *base_value* converted from *base_unit* to the greatest + possible human-friendly unit, or *base_value* string if conversion failed. + + :Example: + + >>> maybe_convert_from_base_unit('5', 'integer', 'ms') + '5ms' + + >>> maybe_convert_from_base_unit('4.2', 'real', 'ms') + '4200us' + + >>> maybe_convert_from_base_unit('on', 'bool', None) + 'on' + + >>> maybe_convert_from_base_unit('', 'integer', '256MB') + '' + """ + converters: Dict[str, Tuple[Callable[[str, Optional[str]], Union[int, float, str, None]], + Callable[[Any, Optional[str]], Optional[str]]]] = { + 'integer': (parse_int, convert_int_from_base_unit), + 'real': (parse_real, convert_real_from_base_unit), + 'default': (lambda v, _: v, lambda v, _: v) + } + parser, converter = converters.get(vartype, converters['default']) + parsed_value = parser(base_value, None) + if parsed_value: + return converter(parsed_value, base_unit) or base_value + return base_value def parse_int(value: Any, base_unit: Optional[str] = None) -> Optional[int]: diff --git a/tests/test_postgresql.py b/tests/test_postgresql.py index aebffc432..59c9eb59c 100644 --- a/tests/test_postgresql.py +++ b/tests/test_postgresql.py @@ -606,9 +606,9 @@ def test_reload_config(self, mock_warning, mock_info): config['parameters']['max_worker_processes'] *= 2 with patch('patroni.postgresql.Postgresql._query', Mock(side_effect=[GET_PG_SETTINGS_RESULT, [(1,)]])): self.p.reload_config(config) - self.assertEqual(mock_info.call_args_list[0][0], ('Changed %s from %s to %s (restart might be required)', - 'max_worker_processes', str(init_max_worker_processes), - config['parameters']['max_worker_processes'])) + self.assertEqual(mock_info.call_args_list[0][0], + ("Changed %s from '%s' to '%s' (restart might be required)", 'max_worker_processes', + str(init_max_worker_processes), config['parameters']['max_worker_processes'])) self.assertEqual(mock_info.call_args_list[1][0], ('Reloading PostgreSQL configuration.',)) self.assertEqual(self.p.pending_restart, True) @@ -617,9 +617,9 @@ def test_reload_config(self, mock_warning, mock_info): # Reset to the initial value without restart config['parameters']['max_worker_processes'] = init_max_worker_processes self.p.reload_config(config) - self.assertEqual(mock_info.call_args_list[0][0], ('Changed %s from %s to %s', 'max_worker_processes', + self.assertEqual(mock_info.call_args_list[0][0], ("Changed %s from '%s' to '%s'", 'max_worker_processes', init_max_worker_processes * 2, - str(config['parameters']['max_worker_processes']))) + config['parameters']['max_worker_processes'])) self.assertEqual(mock_info.call_args_list[1][0], ('Reloading PostgreSQL configuration.',)) self.assertEqual(self.p.pending_restart, False) @@ -628,20 +628,21 @@ def test_reload_config(self, mock_warning, mock_info): # User-defined parameter changed (removed) config['parameters'].pop('f.oo') self.p.reload_config(config) - self.assertEqual(mock_info.call_args_list[0][0], ('Changed %s from %s to %s', 'f.oo', 'bar', None)) + self.assertEqual(mock_info.call_args_list[0][0], ("Changed %s from '%s' to '%s'", 'f.oo', 'bar', None)) self.assertEqual(mock_info.call_args_list[1][0], ('Reloading PostgreSQL configuration.',)) self.assertEqual(self.p.pending_restart, False) mock_info.reset_mock() # Non-postmaster parameter change - config['parameters']['autovacuum'] = 'off' + config['parameters']['vacuum_cost_delay'] = 2.5 self.p.reload_config(config) - self.assertEqual(mock_info.call_args_list[0][0], ("Changed %s from %s to %s", 'autovacuum', 'on', 'off')) + self.assertEqual(mock_info.call_args_list[0][0], + ("Changed %s from '%s' to '%s'", 'vacuum_cost_delay', '200ms', 2.5)) self.assertEqual(mock_info.call_args_list[1][0], ('Reloading PostgreSQL configuration.',)) self.assertEqual(self.p.pending_restart, False) - config['parameters']['autovacuum'] = 'on' + config['parameters']['vacuum_cost_delay'] = 200 mock_info.reset_mock() # Remove invalid parameter @@ -832,6 +833,11 @@ def test_effective_configuration(self, mock_logger): self.assertFalse(self.p.start()) mock_logger.warning.assert_not_called() self.assertTrue(self.p.pending_restart) + mock_logger.info.assert_called_once() + self.assertEqual(mock_logger.info.call_args[0], + ("%s value in pg_controldata: %d, in the global configuration: %d." + " pg_controldata value will be used. Setting 'Pending restart' flag", + 'max_wal_senders', 10, 5)) @patch('os.path.exists', Mock(return_value=True)) @patch('os.path.isfile', Mock(return_value=False))