python logging demystified!
===========================

disclaimer
----------

.. _reference: https://docs.python.org/2/library/logging.html

This has been written with the latest version of Python 2 in mind
(currently 2.7.9), and while the general premise holds true for
Python 3, some of the details may have small differences
from how it would be done in Python 3.

Of course, for further insight into the workings of the Python
logging module, I would encourage you to take a look at their
`official documentation`__ for an authoritative reference.

.. __: reference_


simplest setup
--------------

.. _practices: http://victorlin.me/posts/2012/08/26/good-logging-practice-in-python

Even just for simple scripts, it really is a good habit to start using
the built in Python logging module instead of print, even for
writing simple information to the console. Here, you can find a few
`good logging practices for Python`__.

.. __: practices_

There seems to be a myth that changing from ``print`` to using the
logging module is too complicated, or too much work. There was a time
where thought the exact same thing, but it turns out I was mistaken!
The simple truth is that the most basic logging configuration is
actually only an extra 1 or 2 lines added your code, but provides a
large amount of value.

To simply output messages to stdout as you would do with print, there
is no complex setup, in fact, you can just use Python's default
configuration by simply importing the module:

.. code:: python

    import logging

    # print 'some message'
    logging.info('some message')

Their default configuration is probably not ideal if writing plain
messages to the console is all you're looking for. Adding one more
line of code provides an easy way to do basic tweaking to the setup
of subsequent logging:

.. code:: python

    import logging
    logging.basicConfig(format='%(message)s', level=logging.DEBUG)
    logging.info('some message')

If you want to log to a file instead of the console, its only a
matter of adding a couple of additional parameters:

.. code:: python

    import logging
    logging.basicConfig(
        filename='myapp.log',
        filemode='w',
        format='%(message)s',
        level=logging.DEBUG
        )
    logging.info('some message')

It is important to note that in a multithreaded project, or one
where you will be logging from multiple modules, its good practice
to configure logging from the main application entry point to
avoid potential state inconsistencies:

.. code:: python

    import logging

    if __name__ == '__main__':
        logging.basicConfig(
            filename='myapp.log',
            filemode='w',
            format='%(message)s',
            level=logging.DEBUG
            )
        logging.info('some message')


further config
--------------

There may be times when you won't know certain things until the
time of execution (passing a filename as a command line argument,
for example). In this case, it might make sense to write a more
malleable setup function for your logging, which you could then
even move to a utils file for your project:

.. code:: python

    # __main__.py
    import logging

    def customize_logging(fname=None, fmt=None, dfmt=none, level=None):
        """
        logging.basicConfig parameters:
        :param filename: use a FileHandler with file filename
        :param filemode: mode to open file in if filename is specified
        :param format: use this format string for the handler
        :param datefmt: use this to format date/time
        :param level: set the root logger to this level
        """
        bc_args = {}
        if fname:
            bc_args['filename'] = fname
            bc_args['filemode'] = 'w'
        if fmt:
            bc_args['format'] = fmt
        if dfmt:
            bc_args['datefmt'] = dfmt
        if level:
            bc_args['level'] = level
        logging.basicConfig(**bc_args)

    if __name__ == '__main__':
        customize_logging(
            fname='myapp.log',
            fmt='\n[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s',
            dfmt='%Y-%m-%d %H:%M:%S',
            level=logging.DEBUG
            )
        logging.info('some message')

One of the largest benefits to using logging over print (IMHO) is
that it allows you to write output statements into your code without
hesitation, knowing that you can always easily modify the logging
config later (like adding a FileHandler or changing the formatting,
for instance) in a single location, without ever having to search
for every place where there is an output statement.


named loggers
-------------

**coming soon!**


custom config
-------------

Building upon the basic config, it actually takes a surprisingly
small amount of work to further customize logging by adding more
handlers or altering the output formatting, and that code can be
wrapped up in a function if desired:

.. code:: python

    import logging

    def customize_logging():
        # gets a named logger using the module path of this file
        log = logging.getLogger(__name__)

        # don't propagate to base loggers
        log.propagate = False

        # make sure we log everything all the way down to debug statements
        log.setLevel(logging.DEBUG)

        # create custom format for log messages
        formatter = logging.Formatter(
            fmt='\n[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s',
            datefmt='%Y-%m-%d %H:%M:%S'
            )

        # a StreamHandler object writes to the terminal by default, but
        # one of the benefits of doing custom logging setup is using a
        # file handler for logging to files!
        handler = logging.StreamHandler()

        # add formatting to the console handler
        handler.setFormatter(formatter)

        # don't forget to add the handler to the logger
        log.addHandler(handler)
        return log


config via json
---------------

**coming soon!**


exception logging
-----------------

.. _exception_gist: https://gist.github.com/zonca/6782980
.. _log_exceptions: stackoverflow.com/questions/4508849/how-to-log-python-exception#4510206
.. _excepthook: http://blog.tplus1.com/blog/2012/08/05/python-log-uncaught-exceptions-with-sys-excepthook/
.. _launch_pdb: http://stackoverflow.com/questions/1237379/how-do-i-set-sys-excepthook-to-invoke-pdb-globally-in-python#1237407

A very important use-case for logging is to output exception info,
particularly when program execution will continue. `Here is a Gist`__
which has examples of catching and logging exceptions.

.. __: exception_gist_

.. code:: python

    import logging


    def exceptions_with_logging(logger):
        try:
            raise ValueError('ERROR_1')
        except:
            # you can use the normal logging methods and set the
            # exception info param to True and let it do the work for you
            logger.error('caught exception', exc_info=True)

        try:
            raise ValueError('ERROR_2')
        except:
            # you can also use the logging exception method as a shortcut
            # to print almost the same information
            logger.exception('caught exception')

        try:
            raise ValueError('ERROR_3')
        except Exception as exc:
            # alternatively you can use a combination of your own formatting
            # with the exception info parameter
            logger.error('[%s] %s' % (exc.__class__.__name__, exc), exc_info=True)


    def setup_logger():
        """
        its not strictly necessary to configure the logging, but its
        usually a good idea, and necessary most of the time for anything
        aside from simple scripts... but technically you can just
        ``import logging`` and start using it without messing with config
        """
        # gets a named logger using the module path of this file
        log = logging.getLogger(__name__)

        # don't propagate to base loggers
        log.propagate = False

        # make sure we log everything all the way down to debug statements
        log.setLevel(logging.DEBUG)

        # create custom format for log messages
        formatter = logging.Formatter(
            fmt='\n[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s',
            datefmt='%Y-%m-%d %H:%M:%S'
            )

        # a StreamHandler object writes to the terminal by default, but
        # one of the benefits of doing custom logging setup is using a
        # file handler for logging to files!
        handler = logging.StreamHandler()

        # add formatting to the console handler
        handler.setFormatter(formatter)

        # don't forget to add the handler to the logger
        log.addHandler(handler)
        return log


    if __name__ == '__main__':
        """
        the name == main thing is common in scripts and modules which have
        code to be executed only when actually 'running' it. This prevents
        running code if this module is simply imported and not 'run'

        >>>
        ERROR:root:caught exception
        Traceback (most recent call last):
          File "<stdin>", line 3, in exceptions_with_logging
        ValueError: ERROR_1

        ERROR:root:caught exception
        Traceback (most recent call last):
          File "<stdin>", line 9, in exceptions_with_logging
        ValueError: ERROR_2

        ERROR:root:[ValueError] ERROR_3
        Traceback (most recent call last):
          File "<stdin>", line 15, in exceptions_with_logging
        ValueError: ERROR_3

        [2015-02-19 12:18:42] INFO [__main__:42] 
        --- CUSTOM LOGGING STARTS HERE ---

        [2015-02-19 12:18:42] ERROR [__main__:7] caught exception
        Traceback (most recent call last):
          File "<stdin>", line 3, in exceptions_with_logging
        ValueError: ERROR_1

        [2015-02-19 12:18:42] ERROR [__main__:13] caught exception
        Traceback (most recent call last):
          File "<stdin>", line 9, in exceptions_with_logging
        ValueError: ERROR_2

        [2015-02-19 12:18:42] ERROR [__main__:19] [ValueError] ERROR_3
        Traceback (most recent call last):
          File "<stdin>", line 15, in exceptions_with_logging
        ValueError: ERROR_3
        >>>
        """
        # run the exceptions using the base logging
        exceptions_with_logging(logging)

        # now lets run the same tests as before, but with the configured
        # logger instead of the default one
        log = setup_logger()
        log.info('\n--- CUSTOM LOGGING STARTS HERE ---\n')
        exceptions_with_logging(log)

If you require more advanced manipulation of exception information,
then you can use the sys + traceback modules to extract and format
the information before logging it, `see this for examples`__.

.. __: log_exceptions_

Luckily, it is also relatively trivial to `handle uncaught exceptions`__
which can be quite useful in certain situations; not all libs will
document all of the exceptions they might raise, for example.

.. __: excepthook_

.. code:: python

    import logging
    import sys
    import traceback

    def global_catch(exc_type, exc_value, traceback):
        log = logging.getLogger(__name__)
        logging.critical(''.join(traceback.format_tb(tb)))
        logging.critical('{0}: {1}'.format(ex_cls, ex))

    # the original value when program execution began is stored in
    # sys.__excepthook__ in case it needs to be restored
    # https://docs.python.org/2/library/sys.html
    sys.excepthook = global_catch

Whether or not you are concerned with logging uncaught exceptions,
you can use this hook to `automatically launch pdb`__
in reponse to an unhandled exception.

.. __: launch_pdb_

.. code:: python

    # coming soon!