Fix bugs introduced in the jsonlog implementation (#3006)

1. RotatingFileHandler is a child of StreamHandler, therefore we can't rely on `not isinstance(handler, logging.StreamHandler)`.
2. If the legacy version of `python-json-logger` is installed (that doesn't support rename_fields or static_fields), we want do what is possible rather than fail with the exception.

Besides that:
1. improve code coverage
2. make unit tests pass without python-json-logger installed or if only some old version is installed.

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
 

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:

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

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