diff --git a/patroni/log.py b/patroni/log.py index 9d639942..beaacf4e 100644 --- a/patroni/log.py +++ b/patroni/log.py @@ -9,11 +9,13 @@ import sys from copy import deepcopy from logging.handlers import RotatingFileHandler -from patroni.utils import deep_compare from queue import Queue, Full from threading import Lock, Thread from typing import Any, Dict, List, Optional, Union, TYPE_CHECKING + +from .utils import deep_compare + type_logformat = Union[List[Union[str, Dict[str, Any], Any]], str, Any] _LOGGER = logging.getLogger(__name__) @@ -349,17 +351,18 @@ class PatroniLogger(Thread): try: from pythonjsonlogger import jsonlogger - formatter = jsonlogger.JsonFormatter( + return jsonlogger.JsonFormatter( jsonformat, dateformat, rename_fields=rename_fields, static_fields=static_fields ) except ImportError as e: - _LOGGER.error('Failed to import "python-json-logger" library. Falling back to the plain logger: %r', e) - formatter = self._get_plain_formatter(jsonformat, dateformat) + _LOGGER.error('Failed to import "python-json-logger" library: %r. Falling back to the plain logger', e) + except Exception as e: + _LOGGER.error('Failed to initialize JsonFormatter: %r. Falling back to the plain logger', e) - return formatter + return self._get_plain_formatter(jsonformat, dateformat) def _get_formatter(self, config: Dict[str, Any]) -> logging.Formatter: """Returns a logging formatter based on the type of logger in the given configuration. @@ -412,9 +415,10 @@ class PatroniLogger(Thread): handler.maxBytes = int(config.get('file_size', 25000000)) # pyright: ignore [reportGeneralTypeIssues] handler.backupCount = int(config.get('file_num', 4)) - else: - if not isinstance(handler, logging.StreamHandler): - handler = logging.StreamHandler() + # we can't use `if not isinstance(handler, logging.StreamHandler)` below, + # because RotatingFileHandler is a child of StreamHandler!!! + elif handler is None or isinstance(handler, RotatingFileHandler): + handler = logging.StreamHandler() is_new_handler = handler != self.log_handler diff --git a/patroni/validator.py b/patroni/validator.py index 70066b9b..a2818a11 100644 --- a/patroni/validator.py +++ b/patroni/validator.py @@ -52,9 +52,9 @@ def validate_log_format(logformat: type_logformat) -> bool: return True elif isinstance(logformat, list): if len(logformat) == 0: - raise ConfigParseError('should contains at least one item') + raise ConfigParseError('should contain at least one item') if not all(map(validate_log_field, logformat)): - raise ConfigParseError('Each item should be a string or a dictionary with string values') + raise ConfigParseError('each item should be a string or a dictionary with string values') return True else: diff --git a/tests/test_log.py b/tests/test_log.py index 4e35bc1d..48020ff4 100644 --- a/tests/test_log.py +++ b/tests/test_log.py @@ -3,7 +3,6 @@ import os import sys import unittest import yaml -import json from io import StringIO from mock import Mock, patch @@ -11,6 +10,16 @@ from patroni.config import Config from patroni.log import PatroniLogger from queue import Queue, Full +try: + from pythonjsonlogger import jsonlogger + + jsonlogger.JsonFormatter(None, None, rename_fields={}, static_fields={}) + json_formatter_is_available = True + + import json # we need json.loads() function +except Exception: + json_formatter_is_available = False + _LOG = logging.getLogger(__name__) @@ -95,13 +104,14 @@ class TestPatroniLogger(unittest.TestCase): logger.reload_config(config) _LOG.info(test_message) - target_log = json.loads(stderr_output.getvalue()) + if json_formatter_is_available: + target_log = json.loads(stderr_output.getvalue().split('\n')[-2]) - self.assertIn('@timestamp', target_log) - self.assertEqual(target_log['message'], test_message) - self.assertEqual(target_log['level'], 'INFO') - self.assertEqual(target_log['app'], 'patroni') - self.assertEqual(len(target_log), len(config['format']) + len(config['static_fields'])) + self.assertIn('@timestamp', target_log) + self.assertEqual(target_log['message'], test_message) + self.assertEqual(target_log['level'], 'INFO') + self.assertEqual(target_log['app'], 'patroni') + self.assertEqual(len(target_log), len(config['format']) + len(config['static_fields'])) def test_json_str_format(self): config = { @@ -119,12 +129,13 @@ class TestPatroniLogger(unittest.TestCase): logger.reload_config(config) _LOG.info(test_message) - target_log = json.loads(stderr_output.getvalue()) + if json_formatter_is_available: + target_log = json.loads(stderr_output.getvalue().split('\n')[-2]) - self.assertIn('asctime', target_log) - self.assertEqual(target_log['message'], test_message) - self.assertEqual(target_log['levelname'], 'INFO') - self.assertEqual(target_log['app'], 'patroni') + self.assertIn('asctime', target_log) + self.assertEqual(target_log['message'], test_message) + self.assertEqual(target_log['levelname'], 'INFO') + self.assertEqual(target_log['app'], 'patroni') def test_plain_format(self): config = { @@ -215,13 +226,10 @@ class TestPatroniLogger(unittest.TestCase): captured_log_message = captured_log.records[0].message self.assertEqual(captured_log_level, 'WARNING') - self.assertRegex( - captured_log_message, - r'Expected log format to be a string or a list, but got ".*"' - ) + self.assertRegex(captured_log_message, r'Expected log format to be a string or a list, but got ".*"') with self.assertLogs() as captured_log: - config['format'] = ['message', ['levelname']] + config['format'] = [['levelname']] logger.reload_config(config) captured_log_level = captured_log.records[0].levelname @@ -234,30 +242,20 @@ class TestPatroniLogger(unittest.TestCase): ) with self.assertLogs() as captured_log: - config['format'] = [ - 'message', - {'asctime': ['timestamp']} - ] + config['format'] = ['message', {'asctime': ['timestamp']}] logger.reload_config(config) captured_log_level = captured_log.records[0].levelname captured_log_message = captured_log.records[0].message self.assertEqual(captured_log_level, 'WARNING') - self.assertRegex( - captured_log_message, - r'Expected renamed log field to be a string, but got ".*"' - ) - - @patch('pythonjsonlogger.jsonlogger.JsonFormatter', side_effect=ImportError) - def test_fail_to_import_python_json_logger(self, _): - config = { - 'type': 'json' - } + self.assertRegex(captured_log_message, r'Expected renamed log field to be a string, but got ".*"') + def test_fail_to_use_python_json_logger(self): with self.assertLogs() as captured_log: logger = PatroniLogger() - logger.reload_config(config) + with patch('builtins.__import__', Mock(side_effect=ImportError)): + logger.reload_config({'type': 'json'}) captured_log_level = captured_log.records[0].levelname captured_log_message = captured_log.records[0].message @@ -265,5 +263,21 @@ class TestPatroniLogger(unittest.TestCase): self.assertEqual(captured_log_level, 'ERROR') self.assertRegex( captured_log_message, - r'Failed to import "python-json-logger" library. Falling back to the plain logger' + r'Failed to import "python-json-logger" library: .*. Falling back to the plain logger' + ) + + with self.assertLogs() as captured_log: + logger = PatroniLogger() + pythonjsonlogger = Mock() + pythonjsonlogger.jsonlogger.JsonFormatter = Mock(side_effect=Exception) + with patch('builtins.__import__', Mock(return_value=pythonjsonlogger)): + logger.reload_config({'type': 'json'}) + + captured_log_level = captured_log.records[0].levelname + captured_log_message = captured_log.records[0].message + + self.assertEqual(captured_log_level, 'ERROR') + self.assertRegex( + captured_log_message, + r'Failed to initialize JsonFormatter: .*. Falling back to the plain logger' ) diff --git a/tests/test_validator.py b/tests/test_validator.py index f70b387b..1c000c1c 100644 --- a/tests/test_validator.py +++ b/tests/test_validator.py @@ -378,31 +378,23 @@ class TestValidator(unittest.TestCase): c["log"]["type"] = "json" c["log"]["format"] = {"levelname": "level"} errors = schema(c) - self.assertIn( - 'log.format {\'levelname\': \'level\'} didn\'t pass validation: Should be a string or a list', - errors - ) + self.assertIn("log.format {'levelname': 'level'} didn't pass validation: Should be a string or a list", errors) + + c["log"]["format"] = [] + errors = schema(c) + self.assertIn("log.format [] didn't pass validation: should contain at least one item", errors) - c = copy.deepcopy(config) - c["log"]["type"] = "json" c["log"]["format"] = [{"levelname": []}] errors = schema(c) - self.assertIn( - ' '.join([ - 'log.format [{\'levelname\': []}] didn\'t pass validation:', - 'Each item should be a string or a dictionary with string values' - ]), - errors - ) + self.assertIn("log.format [{'levelname': []}] didn't pass validation: " + "each item should be a string or a dictionary with string values", errors) - c = copy.deepcopy(config) - c["log"]["type"] = "json" c["log"]["format"] = [[]] errors = schema(c) - self.assertIn( - ' '.join([ - 'log.format [[]] didn\'t pass validation:', - 'Each item should be a string or a dictionary with string values' - ]), - errors - ) + self.assertIn("log.format [[]] didn't pass validation: " + "each item should be a string or a dictionary with string values", errors) + + c["log"]["format"] = ['foo'] + errors = schema(c) + output = "\n".join(errors) + self.assertEqual(['postgresql.bin_dir', 'raft.bind_addr', 'raft.self_addr'], parse_output(output))