Improve logging for Pg param change (patroni#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

@@ -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

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]:

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))