Make it possible to configure log level for exception tracebacks (#1311)

If you set `log.traceback_level=DEBUG`, the tracebacks will be visible only when `log.level=DEBUG`. The default behavior remains the same.

docs/ENVIRONMENT.rst

@@ -15,6 +15,7 @@ Global/Universal
 Log
 ---
 -  **PATRONI\_LOG\_LEVEL**: sets the general logging level. Default value is **INFO** (see `the docs for Python logging <https://docs.python.org/3.6/library/logging.html#levels>`_)
+-  **PATRONI\_LOG\_TRACEBACK\_LEVEL**: sets the level where tracebacks will be visible. Default value is **ERROR**. Set it to **DEBUG** if you want to see tracebacks only if you enable **PATRONI\_LOG\_LEVEL=DEBUG**.
 -  **PATRONI\_LOG\_FORMAT**: sets the log formatting string. Default value is **%(asctime)s %(levelname)s: %(message)s** (see `the LogRecord attributes <https://docs.python.org/3.6/library/logging.html#logrecord-attributes>`_)
 -  **PATRONI\_LOG\_DATEFORMAT**: sets the datetime formatting string. (see the `formatTime() documentation <https://docs.python.org/3.6/library/logging.html#logging.Formatter.formatTime>`_)
 -  **PATRONI\_LOG\_MAX\_QUEUE\_SIZE**: Patroni is using two-step logging. Log records are written into the in-memory queue and there is a separate thread which pulls them from the queue and writes to stderr or file. The maximum size of the internal queue is limited by default by **1000** records, which is enough to keep logs for the past 1h20m.

docs/SETTINGS.rst

@@ -46,6 +46,7 @@ Global/Universal
 Log
 ---
 -  **level**: sets the general logging level. Default value is **INFO** (see `the docs for Python logging <https://docs.python.org/3.6/library/logging.html#levels>`_)
+-  **traceback\_level**: sets the level where tracebacks will be visible. Default value is **ERROR**. Set it to **DEBUG** if you want to see tracebacks only if you enable **log.level=DEBUG**.
 -  **format**: sets the log formatting string. Default value is **%(asctime)s %(levelname)s: %(message)s** (see `the LogRecord attributes <https://docs.python.org/3.6/library/logging.html#logrecord-attributes>`_)
 -  **dateformat**: sets the datetime formatting string. (see the `formatTime() documentation <https://docs.python.org/3.6/library/logging.html#logging.Formatter.formatTime>`_)
 -  **max\_queue\_size**: Patroni is using two-step logging. Log records are written into the in-memory queue and there is a separate thread which pulls them from the queue and writes to stderr or file. The maximum size of the internal queue is limited by default by **1000** records, which is enough to keep logs for the past 1h20m.

patroni/config.py

@@ -242,7 +242,7 @@ class Config(object):
         _set_section_values('restapi', ['listen', 'connect_address', 'certfile', 'keyfile', 'cafile', 'verify_client'])
         _set_section_values('ctl', ['insecure', 'cacert', 'certfile', 'keyfile'])
         _set_section_values('postgresql', ['listen', 'connect_address', 'config_dir', 'data_dir', 'pgpass', 'bin_dir'])
-        _set_section_values('log', ['level', 'format', 'dateformat', 'max_queue_size',
+        _set_section_values('log', ['level', 'traceback_level', 'format', 'dateformat', 'max_queue_size',
                                     'dir', 'file_size', 'file_num', 'loggers'])
 
         def _parse_dict(value):

patroni/log.py

@@ -11,6 +11,20 @@ from threading import Lock, Thread
 _LOGGER = logging.getLogger(__name__)
 
 
+def debug_exception(logger_obj, msg, *args, **kwargs):
+    kwargs.pop("exc_info", False)
+    if logger_obj.isEnabledFor(logging.DEBUG):
+        logger_obj.debug(msg, *args, exc_info=True, **kwargs)
+    else:
+        msg = "{0}, DETAIL: '{1}'".format(msg, sys.exc_info()[1])
+        logger_obj.error(msg, *args, exc_info=False, **kwargs)
+
+
+def error_exception(logger_obj, msg, *args, **kwargs):
+    exc_info = kwargs.pop("exc_info", True)
+    logger_obj.error(msg, *args, exc_info=exc_info, **kwargs)
+
+
 class QueueHandler(logging.Handler):
 
     def __init__(self):
@@ -61,6 +75,7 @@ class ProxyHandler(logging.Handler):
 class PatroniLogger(Thread):
 
     DEFAULT_LEVEL = 'INFO'
+    DEFAULT_TRACEBACK_LEVEL = 'ERROR'
     DEFAULT_FORMAT = '%(asctime)s %(levelname)s: %(message)s'
 
     NORMAL_LOG_QUEUE_SIZE = 2  # When everything goes normal Patroni writes only 2 messages per HA loop
@@ -99,6 +114,10 @@ class PatroniLogger(Thread):
                 self._queue_handler.queue.maxsize = config.get('max_queue_size', self.DEFAULT_MAX_QUEUE_SIZE)
 
             self._root_logger.setLevel(config.get('level', PatroniLogger.DEFAULT_LEVEL))
+            if config.get('traceback_level', PatroniLogger.DEFAULT_TRACEBACK_LEVEL).lower() == 'debug':
+                logging.Logger.exception = debug_exception
+            else:
+                logging.Logger.exception = error_exception
 
             new_handler = None
             if 'dir' in config:

tests/test_log.py

@@ -22,6 +22,7 @@ class TestPatroniLogger(unittest.TestCase):
     def test_patroni_logger(self):
         config = {
             'log': {
+                'traceback_level': 'DEBUG',
                 'max_queue_size': 5,
                 'dir': 'foo',
                 'file_size': 4096,
@@ -50,7 +51,7 @@ class TestPatroniLogger(unittest.TestCase):
             logger.reload_config(config['log'])
             with patch.object(logging.Logger, 'makeRecord',
                               Mock(side_effect=[logging.LogRecord('', logging.INFO, '', 0, '', (), None), Exception])):
-                logging.error('test')
+                logging.exception('test')
             logging.error('test')
             with patch.object(Queue, 'put_nowait', Mock(side_effect=Full)):
                 self.assertRaises(SystemExit, logger.shutdown)