Improve the logging system

Each module or Consumer now uses its own logger. This allows to finely
tune which messages get to the log output.

To allow the final user to customize every aspect of the logs, an
additional configuration parameter `logging` is added to sauna.yml.

doc/user/configuration.rst

@@ -67,6 +67,11 @@ All these parameters can be left out, in this case they take their default value
     Note that activating the concurrency system will, by default, only allow 1 check with the same name to run at the
     same time.
 
+**logging**
+    Sauna writes logs to the standard output by default. The ``logging`` parameter allows to pass a custom logging
+    configuration to change the log format, write logs to files, send them to syslog and much more. Check the
+    :ref:`logging syntax<logging_syntax>` for the details.
+
 Example::
 
     ---
@@ -154,3 +159,41 @@ Check parameters
 **periodicity**
     Optional, overrides the global periodicity for this check. Used to run a check at a different
     frequency than the others.
+
+.. _logging_syntax:
+
+Logging syntax
+~~~~~~~~~~~~~~
+
+By default Sauna writes logs with the level ``WARNING`` or the level passed by the
+``--level`` flag in the command line to the standard output.
+
+To further customize how logs are processed, Sauna can also leverage `Python dictConfig
+<https://docs.python.org/3/library/logging.config.html#dictionary-schema-details>`_. This allows the user to modify
+every aspect of the logging system, for instance:
+
+* Storing the logs in a file rotating every week
+* Silencing some log message but not others
+* Forwarding logs to syslog
+* Modifying the format of the logs
+
+To do that a dictionary configuration must be passed in the ``logging`` parameter of the configuration file. For
+example to remove the date from the record and write the message to stderr::
+
+    ---
+    logging:
+      version: 1
+      formatters:
+        simple:
+          format: '%(message)s'
+      handlers:
+        console:
+          class: logging.StreamHandler
+          formatter: simple
+          stream: ext://sys.stderr
+      root:
+        level: DEBUG
+        handlers: [console]
+
+Make sure to read the `Python logging documentation
+<https://docs.python.org/3/howto/logging.html#advanced-logging-tutorial>`_ to go further.

sauna/__init__.py

@@ -1,7 +1,7 @@
 from collections import namedtuple
 import threading
 import queue
-import logging
+from logging import getLogger
 import time
 import socket
 import os
@@ -23,6 +23,7 @@
 from sauna.scheduler import Scheduler, Job
 
 __version__ = '0.0.16'
+logger = getLogger(__name__)
 
 ServiceCheck = namedtuple('ServiceCheck',
                           ['timestamp', 'hostname', 'name',
@@ -287,14 +288,14 @@ def launch_and_publish_checks_with_periodicity(self, periodicity):
                         self._current_checks.append(check.name)
                         self._thread_pool.submit(self._check_helper, check)
                     else:
-                        logging.debug(
+                        logger.debug(
                             "Skipping {}, already being checked".format(
                                 check.name))
 
     def _check_helper(self, check):
         service_check = self.launch_check(check)
-        logging.debug('Pushing check {} to {} synchronous consumers'.
-                      format(service_check.name, len(self._consumers_queues)))
+        logger.debug('Pushing check {} to {} synchronous consumers'.
+                     format(service_check.name, len(self._consumers_queues)))
         self.send_data_to_consumers(service_check)
         with check_results_lock:
             check_results[service_check.name] = service_check
@@ -307,7 +308,7 @@ def launch_check(self, check):
         try:
             status, output = check.run_check()
         except Exception as e:
-            logging.warning('Could not run check {}: {}'.format(
+            logger.warning('Could not run check {}: {}'.format(
                 check.name, str(e)
             ))
             status = 3
@@ -325,23 +326,23 @@ def run_producer(self):
                          for check in self.get_all_active_checks()}
         jobs = [Job(p, self.launch_and_publish_checks_with_periodicity, p)
                 for p in periodicities]
-        logging.info('Running checks with interval: {}'
-                     .format(str(periodicities)))
+        logger.info('Running checks with interval: {}'
+                    .format(str(periodicities)))
         scheduler = Scheduler(jobs)
 
         for _ in scheduler:
             if self.must_stop.wait(timeout=scheduler.tick_duration):
                 break
         if self._thread_pool:
             self._thread_pool.shutdown(wait=False)
-        logging.debug('Exited producer thread')
+        logger.debug('Exited producer thread')
 
     def term_handler(self, *args):
         """Notify producer and consumer that they should stop."""
         if not self.must_stop.is_set():
             self.must_stop.set()
             self.send_data_to_consumers(self.must_stop)
-            logging.info('Exiting...')
+            logger.info('Exiting...')
 
     def send_data_to_consumers(self, data):
         for queue in self._consumers_queues:
@@ -386,7 +387,7 @@ def launch(self):
 
             consumer_thread.start()
             consumers_threads.append(consumer_thread)
-            logging.debug(
+            logger.debug(
                 'Running consumer {}'.format(consumer_name)
             )
 
@@ -401,7 +402,7 @@ def launch(self):
         for consumer_thread in consumers_threads:
             consumer_thread.join()
 
-        logging.debug('Exited main thread')
+        logger.debug('Exited main thread')
 
     @classmethod
     def import_submodules(cls, entity):
@@ -421,14 +422,14 @@ def import_directory_modules(cls, path):
         try:
             entries = os.listdir(path)
         except OSError as e:
-            logging.error('Cannot load plugins from {}: {}'.format(path, e))
+            logger.error('Cannot load plugins from {}: {}'.format(path, e))
             return
-        logging.info('Loading extra plugins from {}'.format(path))
+        logger.info('Loading extra plugins from {}'.format(path))
         sys.path.append(path)
         for entry in entries:
             if not os.path.isfile(os.path.join(path, entry)):
                 continue
             regexp_result = re.search(r'(.+)\.py$', entry)
             if regexp_result:
-                logging.debug('Loading {}'.format(regexp_result.groups()[0]))
+                logger.debug('Loading {}'.format(regexp_result.groups()[0]))
                 cls.import_submodules(regexp_result.groups()[0])

sauna/consumers/base.py

@@ -12,8 +12,16 @@ def __init__(self, config):
         self.stale_age = config.get('stale_age', 300)
         self.retry_delay = 10
 
+    @property
+    def logger(self):
+        return logging.getLogger('sauna.' + self.__class__.__name__)
+
     @classmethod
     def logging(cls, lvl, message):
+        """Log a message.
+
+        Deprecated, use self.logger instead. Kept for backward compatibility
+        """
         log = getattr(logging, lvl)
         message = '[{}] {}'.format(cls.__name__, message)
         log(message)
@@ -39,21 +47,20 @@ def try_send(self, service_check, must_stop):
             if must_stop.is_set():
                 return
             if service_check.timestamp + self.stale_age < int(time.time()):
-                self.logging('warning', 'Dropping check because it is too old')
+                self.logger.warning('Dropping check because it is too old')
                 return
             try:
                 self._send(service_check)
-                self.logging('info', 'Check sent')
+                self.logger.info('Check sent')
                 return
             except Exception as e:
-                self.logging('warning', 'Could not send check: {}'.format(e))
+                self.logger.warning('Could not send check: {}'.format(e))
                 if must_stop.is_set():
                     return
                 self._wait_before_retry(must_stop)
 
     def _wait_before_retry(self, must_stop):
-        self.logging('info',
-                     'Waiting {}s before retry'.format(self.retry_delay))
+        self.logger.info('Waiting {}s before retry'.format(self.retry_delay))
         for i in range(self.retry_delay):
             if must_stop.is_set():
                 return
@@ -65,12 +72,9 @@ def run(self, must_stop, queue):
             service_check = queue.get()
             if isinstance(service_check, event_type):
                 continue
-            self.logging(
-                'debug',
-                'Got check {}'.format(service_check)
-            )
+            self.logger.debug('Got check {}'.format(service_check))
             self.try_send(service_check, must_stop)
-        self.logging('debug', 'Exited consumer thread')
+        self.logger.debug('Exited consumer thread')
 
 
 class AsyncConsumer(Consumer):

sauna/consumers/ext/http_server.py

@@ -1,10 +1,12 @@
 import json
 from http.server import HTTPServer, BaseHTTPRequestHandler
+from logging import getLogger
 
 from sauna.consumers.base import AsyncConsumer
 from sauna.consumers import ConsumerRegister
 from sauna import __version__
 
+logger = getLogger('sauna.HTTPServerConsumer')
 my_consumer = ConsumerRegister('HTTPServer')
 
 
@@ -43,7 +45,7 @@ def run(self, must_stop, *args):
             Handler
         )
         http_server.serve_forever()
-        self.logging('debug', 'Exited consumer thread')
+        self.logger.debug('Exited consumer thread')
 
     @staticmethod
     def config_sample():
@@ -95,7 +97,4 @@ def get_content_from_path(self):
             raise NotFoundError()
 
     def log_message(self, format, *args):
-        HTTPServerConsumer.logging(
-            'debug',
-            '{} - {}'.format(self.address_string(), format % args)
-        )
+        logger.debug('{} {}'.format(self.address_string(), format % args))

sauna/consumers/ext/nsca.py

@@ -134,8 +134,8 @@ def _send(self, service_check):
                 self._last_good_receiver_address = receiver_address
                 return
             except OSError as e:
-                self.logging('info', 'Could not send check to receiver {}: '
-                             '{}'.format(receiver_address, e))
+                self.logger.info('Could not send check to receiver {}: '
+                                 '{}'.format(receiver_address, e))
         raise IOError('No receiver accepted the check')
 
     @staticmethod

sauna/consumers/ext/tcp_server.py

@@ -32,9 +32,7 @@ def _create_server(self):
 
     def _accept_new_connection(self):
         client_socket, address = self.server.accept()
-        self.logging(
-            'debug', 'New connection from {}'.format(address[0])
-        )
+        self.logger.debug('New connection from {}'.format(address[0]))
         self.write_wanted.append(client_socket)
         self.read_wanted.append(client_socket)
         return client_socket
@@ -67,7 +65,7 @@ def _close_socket(self, s):
             del self.write_buffers[s]
         except KeyError:
             pass
-        self.logging('debug', 'Closed connection')
+        self.logger.debug('Closed connection')
 
     @staticmethod
     def _remove_from_list(list_, value):
@@ -89,15 +87,15 @@ def _handle_read_event(self, s):
             try:
                 read_data = s.recv(4096)
             except socket.error as e:
-                self.logging('debug',
-                             'Error while receiving, closing connection: {}'
-                             .format(e))
+                self.logger.debug(
+                    'Error while receiving, closing connection: {}'.format(e)
+                )
                 self._close_socket(s)
                 return
             if len(read_data) == 0:
                 self._close_socket(s)
             else:
-                self.logging('debug', 'Received data')
+                self.logger.debug('Received data')
                 if b'\n' in read_data:
                     to_write = self.get_current_status()[0].encode() + b'\n'
                     self.write_buffers[s] += to_write
@@ -107,15 +105,15 @@ def _handle_write_event(self, s):
         try:
             sent_len = s.send(self.write_buffers[s])
         except socket.error as e:
-            self.logging('debug',
-                         'Error while sending, closing connection: {}'
-                         .format(e))
+            self.logger.debug(
+                'Error while sending, closing connection: {}'.format(e)
+            )
             self._close_socket(s)
             return
         self.write_buffers[s] = self.write_buffers[s][sent_len:]
         if not self.write_buffers[s]:
             self.write_wanted.remove(s)
-            self.logging('debug', 'Sent data')
+            self.logger.debug('Sent data')
 
     def run(self, must_stop, *args):
         self._create_server()
@@ -131,7 +129,7 @@ def run(self, must_stop, *args):
             )
 
             for s in errored:
-                self.logging('debug', 'Connection in error, closing it')
+                self.logger.debug('Connection in error, closing it')
                 self._close_socket(s)
 
             for s in readable:
@@ -140,7 +138,7 @@ def run(self, must_stop, *args):
             for s in writable:
                 self._handle_write_event(s)
 
-        self.logging('debug', 'Exited consumer thread')
+        self.logger.debug('Exited consumer thread')
 
     @staticmethod
     def config_sample():

sauna/main.py

@@ -1,6 +1,8 @@
 #!/usr/bin/env python3
 """Daemon that runs and reports health checks
 
+Documentation https://sauna.readthedocs.io
+
 Usage:
   sauna [--level=<lvl>] [--config=FILE] [<command> <args>...]
   sauna sample
@@ -16,6 +18,7 @@
 Available commands:
 """
 import logging
+import logging.config
 
 from docopt import docopt, DocoptLanguageError
 from yaml.error import YAMLError
@@ -38,11 +41,10 @@ def main():
     args = docopt(doc, version=sauna.__version__, options_first=True)
     conf_file = args['--config']
     logging.basicConfig(
-        format='%(asctime)s - %(levelname)-8s - %(message)s',
+        format='%(asctime)s - %(levelname)-8s - %(name)s: %(message)s',
         datefmt='%Y/%m/%d %H:%M:%S',
         level=getattr(logging, args['--level'].upper(), 'WARN')
     )
-    logging.getLogger('requests').setLevel(logging.ERROR)
 
     # Sample command needs a not configured instance of sauna
     if args.get('<command>') == 'sample':
@@ -57,6 +59,11 @@ def main():
         print('YAML syntax in configuration file {} is not valid: {}'.
               format(conf_file, e))
         exit(1)
+
+    if 'logging' in config:
+        # Override the logging configuration with the one from the config file
+        logging.config.dictConfig(config['logging'])
+
     sauna_instance = sauna.Sauna(config)
 
     # Generic commands implemented in sauna.commands package
@@ -76,3 +83,5 @@ def main():
     # Just run sauna
     else:
         sauna_instance.launch()
+
+    logging.shutdown()