Python logging example (with good practices, in a Django management command and In a standalone Python script) ¶

Quick and dirty ...

import logging
import sys

def set_logger(verbosity, logger_name=__name__):
    logger = logging.getLogger(logger_name)
    levels = [logging.ERROR, logging.WARNING, logging.INFO, logging.DEBUG]
    loglevel = levels[min(len(levels)-1, verbosity)]  # capped to number of levels
    logger.setLevel(loglevel)
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter('%(asctime)s|%(levelname)s|%(module)s| %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger

then:

def handle(self, *args, **options):
    self.logger = set_logger(options['verbosity'])
    ...

Other examples ...

# -*- coding: utf-8 -*-
from __future__ import absolute_import, print_function, unicode_literals

import time
import datetime
import logging
import sys
from django.core.management.base import NoArgsCommand


logger = logging.getLogger(__name__)


class Command(NoArgsCommand):

    def set_logger(self, verbosity):
        """
        Set logger level based on verbosity option
        """
        handler = logging.StreamHandler(sys.stdout)
        formatter = logging.Formatter('%(asctime)s|%(levelname)s|%(module)s| %(message)s')
        handler.setFormatter(formatter)
        logger.addHandler(handler)

        if verbosity == 0:
            self.logger.setLevel(logging.WARN)
        elif verbosity == 1:  # default
            self.logger.setLevel(logging.INFO)
        elif verbosity > 1:
            self.logger.setLevel(logging.DEBUG)

        # verbosity 3: also enable all logging statements that reach the root logger
        if verbosity > 2:
            logging.getLogger().setLevel(logging.DEBUG)

    def __init__(self, logger=None):
        self.logger = logger or logging.getLogger(__name__)

    def elapsed_display(self, t0):
        t = datetime.datetime.now()
        seconds = int((t - t0).total_seconds())
        return time.strftime("%H:%M:%S", time.gmtime(seconds))

    def handle(self, *args, **options):

        tasklist = [sample_task, test_logger_task, ]

        self.set_logger(options.get('verbosity'))

        cron_t0 = datetime.datetime.now()
        self.logger.info('==> cron started.' + '=' * 60)
        for task in tasklist:
            task_t0 = datetime.datetime.now()
            try:
                self.logger.info('--> %s() started.' % task.__name__)
                task()
            except Exception as e:
                logger.error(str(e), exc_info=True)
            finally:
                self.logger.info('<-- %s() finished [%s].' % (
                    task.__name__,
                    self.elapsed_display(task_t0),
                ))
        self.logger.info('<== cron finished [%s]. ' % self.elapsed_display(cron_t0) + '=' * 60)


def sample_task():
    logger.info('work ...')
    logger.info('more work ...')
    logger.info('even more work ...')


def test_logger_task():
    logger.error("boom !")
    logger.debug("This is a debug message")
    logger.info("Informational message")
    logger.error("An error has happened!")
    open('/path/to/does/not/exist', 'rb')

Output:

2017-07-14 12:13:33,803|INFO|aaa| ==> cron started.============================================================
2017-07-14 12:13:33,803|INFO|aaa| --> sample_task() started.
2017-07-14 12:13:33,803|INFO|aaa| work ...
2017-07-14 12:13:33,804|INFO|aaa| more work ...
2017-07-14 12:13:33,804|INFO|aaa| even more work ...
2017-07-14 12:13:33,804|INFO|aaa| <-- sample_task() finished [00:00:00].
2017-07-14 12:13:33,804|INFO|aaa| --> test_logger_task() started.
2017-07-14 12:13:33,804|ERROR|aaa| boom !
2017-07-14 12:13:33,804|INFO|aaa| Informational message
2017-07-14 12:13:33,804|ERROR|aaa| An error has happened!
2017-07-14 12:13:33,804|ERROR|aaa| [Errno 2] No such file or directory: u'/path/to/does/not/exist'
Traceback (most recent call last):
  File "/Users/morlandi/src2/brainstorm/test/test/test/management/commands/aaa.py", line 46, in handle
    task()
  File "/Users/morlandi/src2/brainstorm/test/test/test/management/commands/aaa.py", line 65, in test_logger_task
    open('/path/to/does/not/exist', 'rb')
IOError: [Errno 2] No such file or directory: u'/path/to/does/not/exist'
2017-07-14 12:13:33,805|INFO|aaa| <-- test_logger_task() finished [00:00:00].
2017-07-14 12:13:33,805|INFO|aaa| <== cron finished [00:00:00]. ============================================================

import logging
import sys
import argparse


logger = logging.getLogger(__name__)


def set_logger(verbosity):
    """
    Set logger level based on verbosity option
    """
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter('%(asctime)s|%(levelname)s|%(module)s| %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    if verbosity == 0:
        logger.setLevel(logging.WARN)
    elif verbosity == 1:  # default
        logger.setLevel(logging.INFO)
    elif verbosity > 1:
        logger.setLevel(logging.DEBUG)

    # verbosity 3: also enable all logging statements that reach the root logger
    if verbosity > 2:
        logging.getLogger().setLevel(logging.DEBUG)

...

def main():

    parser = argparse.ArgumentParser(
        description='Receive messages from an UDP socket'
    )
    parser.add_argument('host', type=str)
    parser.add_argument('port', type=int)
    parser.add_argument('--verbosity', '-v', type=int, default=1,
        help="Verbosity level; 0=minimal output, 1=normal output, 2=verbose output, 3=very verbose output")
    args = parser.parse_args()

    set_logger(args.verbosity)

    logger.info('udp_receive started ...')
    receive_udp_messages(args.host, args.port)


if __name__ == "__main__":
    main()