Make logging configurable via YAML file (#927)

It allows changing logging settings in runtime by updating config and doing reload or sending `SIGHUP` to the Patroni process.
Important! Environment configuration names related to logging were renamed and documentation accordingly updated. For compatibility reasons Patroni still accepts `PATRONI_LOGLEVEL` and `PATRONI_FORMAT`, but some other variables related to logging, which were introduced only
recently (between releases), will stop working. I think it is ok, since we didn't release the new version yet and therefore it is very unlikely that somebody is using them except authors of corresponding PRs.

Example of log section in the config file:
```yaml
log:
  dir: /where/to/write/patroni/logs  # if not specified, write logs to stderr
  file_size: 50000000  # 50MB
  file_num: 10  # keep history of 10 files
  dateformat: '%Y-%m-%d %H:%M:%S'
  loggers:  # increase log verbosity for etcd.client and urllib3
    etcd.client: DEBUG
    urllib3: DEBUG
```

docs/ENVIRONMENT.rst

@@ -8,13 +8,16 @@ It is possible to override some of the configuration parameters defined in the P
 Global/Universal
 ----------------
 -  **PATRONI\_CONFIGURATION**: it is possible to set the entire configuration for the Patroni via ``PATRONI_CONFIGURATION`` environment variable. In this case any other environment variables will not be considered!
--  **PATRONI\_FILE\_LOG\_DIR**: Directory to write application logs to. The directory must exist and be writable by the user executing Patroni. If you set this env variable, the application will retain 4 25MB logs by default. You can tune those retention values with PATRONI_LOG_FILE_NUM and PATRONI_LOG_FILE_SIZE (see below).
--  **PATRONI\_FILE\_LOG\_NUM**: The number of application logs to retain.
--  **PATRONI\_FILE\_LOG\_SIZE**: Size of log application log file that triggers a log rolling.
 -  **PATRONI\_NAME**: name of the node where the current instance of Patroni is running. Must be unique for the cluster.
 -  **PATRONI\_NAMESPACE**: path within the configuration store where Patroni will keep information about the cluster. Default value: "/service"
 -  **PATRONI\_SCOPE**: cluster name
--  **PATRONI\_LOGLEVEL**: sets the general logging level (see `the docs for Python logging <https://docs.python.org/3.6/library/logging.html#levels>`_)
+-  **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\_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\_DIR**: Directory to write application logs to. The directory must exist and be writable by the user executing Patroni. If you set this env variable, the application will retain 4 25MB logs by default. You can tune those retention values with `PATRONI_LOG_FILE_NUM` and `PATRONI_LOG_FILE_SIZE` (see below).
+-  **PATRONI\_LOG\_FILE\_NUM**: The number of application logs to retain.
+-  **PATRONI\_LOG\_FILE\_SIZE**: Size of patroni.log file (in bytes) that triggers a log rolling.
+-  **PATRONI\_LOG\_LOGGERS**: Redefine logging level per python module. Example ``PATRONI_LOG_LOGGERS="{patroni.postmaster: WARNING, urllib3: DEBUG}"``
 
 Bootstrap configuration
 -----------------------

docs/SETTINGS.rst

@@ -10,6 +10,18 @@ Global/Universal
 -  **namespace**: path within the configuration store where Patroni will keep information about the cluster. Default value: "/service"
 -  **scope**: cluster name
 
+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>`_)
+-  **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>`_)
+-  **dir**: Directory to write application logs to. The directory must exist and be writable by the user executing Patroni. If you set this value, the application will retain 4 25MB logs by default. You can tune those retention values with `file_num` and `file_size` (see below).
+-  **file\_num**: The number of application logs to retain.
+-  **file\_size**: Size of patroni.log file (in bytes) that triggers a log rolling.
+-  **loggers**: This section allows redefining logging level per python module
+    -  **patroni.postmaster: WARNING**
+    -  **urllib3: DEBUG**
+
 Bootstrap configuration
 -----------------------
 -  **dcs**: This section will be written into `/<namespace>/<scope>/config` of a given configuration store after initializing of new cluster. This is the global configuration for the cluster. If you want to change some parameters for all cluster nodes - just do it in DCS (or via Patroni API) and all nodes will apply this configuration.

patroni/__init__.py

@@ -1,4 +1,3 @@
-from logging.handlers import RotatingFileHandler
 import logging
 import os
 import signal
@@ -15,6 +14,7 @@ class Patroni(object):
         from patroni.config import Config
         from patroni.dcs import get_dcs
         from patroni.ha import Ha
+        from patroni.log import PatroniLogger
         from patroni.postgresql import Postgresql
         from patroni.version import __version__
         from patroni.watchdog import Watchdog
@@ -22,7 +22,9 @@ class Patroni(object):
         self.setup_signal_handlers()
 
         self.version = __version__
+        self.logger = PatroniLogger()
         self.config = Config()
+        self.logger.reload_config(self.config.get('log', {}))
         self.dcs = get_dcs(self.config)
         self.watchdog = Watchdog(self.config)
         self.load_dynamic_configuration()
@@ -67,6 +69,7 @@ class Patroni(object):
     def reload_config(self):
         try:
             self.tags = self.get_tags()
+            self.logger.reload_config(self.config.get('log', {}))
             self.dcs.reload_config(self.config)
             self.watchdog.reload_config(self.config)
             self.api.reload_config(self.config['restapi'])
@@ -140,24 +143,6 @@ class Patroni(object):
 
 
 def patroni_main():
-    logdir = os.environ.get('PATRONI_FILE_LOG_DIR', None)
-    logformat = os.environ.get('PATRONI_LOGFORMAT', '%(asctime)s %(levelname)s: %(message)s')
-    loglevel = os.environ.get('PATRONI_LOGLEVEL', 'INFO')
-    logdatefmt = os.environ.get('PATRONI_LOGDATEFMT', '%Y-%m-%d %H:%M:%S')
-
-    if not logdir:
-        logging.basicConfig(format=logformat, level=loglevel, datefmt=logdatefmt)
-    else:
-        logsize = os.environ.get('PATRONI_FILE_LOG_SIZE', 25000000)
-        lognum = os.environ.get('PATRONI_FILE_LOG_NUM', 4)
-
-        root_logger = logging.getLogger()
-        root_logger.setLevel(loglevel)
-        handler = RotatingFileHandler(os.path.join(logdir, 'patroni.log'), mode='a', maxBytes=logsize,
-                                      backupCount=lognum)
-        handler.setFormatter(logging.Formatter(logformat, logdatefmt))
-        root_logger.addHandler(handler)
-
     patroni = Patroni()
     try:
         patroni.run()

patroni/config.py

@@ -216,6 +216,15 @@ class Config(object):
             if value:
                 ret[param] = value
 
+        def _fix_log_env(name, oldname):
+            value = _popenv(oldname)
+            name = Config.PATRONI_ENV_PREFIX + 'LOG_' + name.upper()
+            if value and name not in os.environ:
+                os.environ[name] = value
+
+        for name, oldname in (('level', 'loglevel'), ('format', 'logformat'), ('dateformat', 'log_datefmt')):
+            _fix_log_env(name, oldname)
+
         def _set_section_values(section, params):
             for param in params:
                 value = _popenv(section + '_' + param)
@@ -224,6 +233,22 @@ class Config(object):
 
         _set_section_values('restapi', ['listen', 'connect_address', 'certfile', 'keyfile'])
         _set_section_values('postgresql', ['listen', 'connect_address', 'data_dir', 'pgpass', 'bin_dir'])
+        _set_section_values('log', ['level', 'format', 'dateformat', 'dir', 'file_size', 'file_num', 'loggers'])
+
+        def _parse_dict(value):
+            if not value.strip().startswith('{'):
+                value = '{{{0}}}'.format(value)
+            try:
+                return yaml.safe_load(value)
+            except Exception:
+                logger.exception('Exception when parsing dict %s', value)
+                return None
+
+        value = ret.get('log', {}).pop('loggers', None)
+        if value:
+            value = _parse_dict(value)
+            if value:
+                ret['log']['loggers'] = value
 
         def _get_auth(name):
             ret = {}
@@ -271,13 +296,7 @@ class Config(object):
                         elif suffix in ('HOSTS', 'PORTS', 'CHECKS'):
                             value = value and _parse_list(value)
                         elif suffix == 'LABELS':
-                            if not value.strip().startswith('{'):
-                                value = '{{{0}}}'.format(value)
-                            try:
-                                value = yaml.safe_load(value)
-                            except Exception:
-                                logger.exception('Exception when parsing dict %s', value)
-                                value = None
+                            value = _parse_dict(value)
                         if value:
                             ret[name.lower()][suffix.lower()] = value
                     # PATRONI_<username>_PASSWORD=<password>, PATRONI_<username>_OPTIONS=<option1,option2,...>

patroni/log.py

@@ -0,0 +1,66 @@
+import logging
+import os
+
+from copy import deepcopy
+from logging.handlers import RotatingFileHandler
+from patroni.utils import deep_compare
+
+
+class PatroniLogger(object):
+
+    DEFAULT_LEVEL = 'INFO'
+    DEFAULT_FORMAT = '%(asctime)s %(levelname)s: %(message)s'
+
+    def __init__(self):
+        self.root_logger = logging.getLogger()
+        self.config = None
+        self.handler = None
+        self.reload_config({'level': 'DEBUG'})
+
+    def update_loggers(self):
+        loggers = deepcopy(self.config.get('loggers') or {})
+        for name, logger in self.root_logger.manager.loggerDict.items():
+            if not isinstance(logger, logging.PlaceHolder):
+                level = loggers.pop(name, logging.NOTSET)
+                logger.setLevel(level)
+
+        for name, level in loggers.items():
+            logger = self.root_logger.manager.getLogger(name)
+            logger.setLevel(level)
+
+    def reload_config(self, config):
+        if self.config is None or not deep_compare(self.config, config):
+            self.root_logger.setLevel(config.get('level', PatroniLogger.DEFAULT_LEVEL))
+
+            add_handler = None
+            if 'dir' in config:
+                if not isinstance(self.handler, RotatingFileHandler):
+                    add_handler = RotatingFileHandler(os.path.join(config['dir'], __name__))
+                handler = add_handler or self.handler
+                handler.maxBytes = int(config.get('file_size', 25000000))
+                handler.backupCount = int(config.get('file_num', 4))
+            else:
+                if self.handler is None or isinstance(self.handler, RotatingFileHandler):
+                    add_handler = logging.StreamHandler()
+                handler = add_handler or self.handler
+
+            oldlogformat = (self.config or {}).get('format', PatroniLogger.DEFAULT_FORMAT)
+            logformat = config.get('format', PatroniLogger.DEFAULT_FORMAT)
+
+            olddateformat = (self.config or {}).get('dateformat') or None
+            dateformat = config.get('dateformat') or None  # Convert empty string to `None`
+
+            if oldlogformat != logformat or olddateformat != dateformat or add_handler:
+                handler.setFormatter(logging.Formatter(logformat, dateformat))
+
+            if add_handler:
+                self.root_logger.addHandler(add_handler)
+
+                if self.handler is not None:
+                    self.root_logger.removeHandler(self.handler)
+                    self.handler.close()
+
+                self.handler = add_handler
+
+            self.config = config.copy()
+            self.update_loggers()

tests/test_config.py

@@ -1,6 +1,6 @@
 import os
-import unittest
 import sys
+import unittest
 
 from mock import MagicMock, Mock, patch
 from patroni.config import Config
@@ -30,6 +30,8 @@ class TestConfig(unittest.TestCase):
             'PATRONI_NAME': 'postgres0',
             'PATRONI_NAMESPACE': '/patroni/',
             'PATRONI_SCOPE': 'batman2',
+            'PATRONI_LOGLEVEL': 'ERROR',
+            'PATRONI_LOG_LOGGERS': 'patroni.postmaster: WARNING, urllib3: DEBUG',
             'PATRONI_RESTAPI_USERNAME': 'username',
             'PATRONI_RESTAPI_PASSWORD': 'password',
             'PATRONI_RESTAPI_LISTEN': '0.0.0.0:8008',

tests/test_log.py

@@ -0,0 +1,38 @@
+import os
+import sys
+import unittest
+import yaml
+
+from mock import Mock, patch
+from patroni.config import Config
+from patroni.log import PatroniLogger
+
+
+class TestPatroniLogger(unittest.TestCase):
+
+    @patch('logging.FileHandler._open', Mock())
+    def setUp(self):
+        self.config = {
+            'log': {
+                'dir': 'foo',
+                'file_size': 4096,
+                'file_num': 5,
+                'loggers': {
+                    'foo.bar': 'INFO'
+                }
+            },
+            'restapi': {}, 'postgresql': {'data_dir': 'foo'}
+        }
+        sys.argv = ['patroni.py']
+        os.environ[Config.PATRONI_CONFIG_VARIABLE] = yaml.dump(self.config, default_flow_style=False)
+        self.logger = PatroniLogger()
+        config = Config()
+        self.logger.reload_config(config['log'])
+
+    def test_rotating_handler(self):
+        self.assertEqual(self.logger.handler.maxBytes, self.config['log']['file_size'])
+        self.assertEqual(self.logger.handler.backupCount, self.config['log']['file_num'])
+
+    def test_reload_config(self):
+        self.config['log'].pop('dir')
+        self.logger.reload_config(self.config['log'])