summarisinglogger.txt

SummarisingLogger
=================

.. note:: 

  Throughout the examples below, mail messages sent using
  :mod:`smtplib` are printed to the screen so we can see what's going on:

  >>> import smtplib
  >>> server = smtplib.SMTP('localhost')
  >>> server.sendmail('from@example.com', ['to@example.com'], 'The message')
  sending to ['to@example.com'] from 'from@example.com' using ('localhost', 25)
  The message

.. currentmodule:: mailinglogger

:class:`SummarisingLogger` is a handler for the python logging
framework that accumulates log entries and sends a single email
containing all the log entries using an SMTP server when its
:meth:`~SummarisingLogger.close` method is called.
This :meth:`~SummarisingLogger.close` method is, by default,
registered as an :mod:`atexit` function so that the summary mail will
get sent regardless of whether an explicit call is made to the
:meth:`SummarisingLogger.close` method. 

:class:`SummarisingLogger` handlers can be very useful for batch
processes that are frequently run and where people would like an email
summary of how the batch run went.
They are configured as any other :mod:`logging` handler would be, full
details of which can be found in the `Python core
documentation`__. For the examples below, we'll stick to manually
configuring the logging elements.

__ http://docs.python.org/howto/logging.html#configuring-logging

A :class:`SummarisingLogger` is instantiated as follows:

>>> import logging
>>> from mailinglogger import SummarisingLogger
>>> handler = SummarisingLogger('from@example.com',('to@example.com',))

It can then be added as a handler for any logger as follows:

>>> import logging
>>> logger = logging.getLogger()
>>> logger.addHandler(handler)

.. invisible-code-block: python

   logger.setLevel(logging.WARNING)
   handler.setLevel(logging.WARNING)
  
However, when we log a message, nothing appears to happen:

>>> logging.debug('some debugging')
>>> logging.info('some information')
>>> logging.warning('a warning')
>>> logging.error('my message')

This is because the messages have been recorded and will be sent as
a summary when the logging framework is shut down or, by default,
when the script that calls the logging function exits.

If we manually close our log handler, we can see the mail gets sent:

>>> handler.close()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
a warning
my message
<BLANKLINE>

The logging on script exit is done using python's :mod:`atexit`
module. Here's the handler registered above:

>>> print(atexit_handlers)
[<bound method SummarisingLogger.close of <...>>]

.. invisible-code-block: python

  atexit_handlers[:] = []

Now, to continue with the examples, just like any other handler, we
can also set the logging level, which will filter out messages logged
below the level set:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',))
>>> logger.addHandler(handler)
>>> handler.setLevel(logging.CRITICAL)
>>> logging.error('an error')
>>> handler.setLevel(logging.WARNING)
>>> logging.warning('a warning')
>>> handler.close()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (WARNING)
To: to@example.com
X-Log-Level: WARNING
X-Mailer: MailingLogger...
<BLANKLINE>
a warning
<BLANKLINE>

As with :class:`MailingLogger`, you can see from the above examples
that :class:`SummarisingLogger` sends mail messages that are correctly
formatted, including ``Date`` and ``Message-ID`` headers.
You will also notice that an ``X-Mailer`` header has been added
specifying that :mod:`mailinglogger` is the sender of the mail.
An ``X-Log-Level`` header has also been added indicating the highest
level message that has been handled by the :class:`SummarisingLogger`.
These headers can be useful for filtering mail
sent by :class:`MailingLogger`. If you wish to filter mail by
environment or other configuration data, the support for adding
:ref:`extra headers <sum_extra_headers>` may be useful.

Avoiding the :mod:`atexit` handler
----------------------------------

.. invisible-code-block: python

  atexit_handlers[:] = []

In the event you wish to manually call the
:meth:`~SummarisingLogger.close` method of the handler or use the
logging framework's :func:`~logging.shutdown` functionality rather 
than registering an :mod:`atexit` function, you can create a
:class:`SummarisingLogger` and specify that no :mod:`atexit` function
should be registered: 

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             atexit=False)
>>> logger.addHandler(handler)

Now, we can see that no :mod:`atexit` function has been registered:

>>> print(atexit_handlers)
[]

With this configuration, if an entry is logged, the logging
framework must be manually shut down for the mail to be sent:

>>> logging.error('my message')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
my message
<BLANKLINE>

Because the users of :class:`SummarisingLogger` may not have control
over when or how often the logging handlers they configure are closed,
a :class:`SummarisingLogger` will not raise exceptions and will not
send duplicate emails if closed more than once:

>>> handler.close()

Likewise, messages logged to the handler after it has been closed
will not result in errors but will also not result in emails being
sent:

>>> logging.error('my message')

Controlling the subject line
----------------------------

The subject for the summary mail sent is controlled by the `subject`
parameter to the :class:`SummarisingLogger` parameter.

This can be set to a fixed value:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             subject='My Logging Summary')
>>> logger.addHandler(handler)
>>> logging.error('a message')
>>> handler.close()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: My Logging Summary
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
a message
<BLANKLINE>

It can also be set using any of the substitution variables described
in the :doc:`subjectformatter` documentation, for example:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             subject='[%(hostname)s] %(levelname)s - %(line)s')
>>> logger.setLevel(logging.INFO)
>>> logger.addHandler(handler)
>>> logging.info('a message')
>>> logging.error('an error')
>>> handler.close()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: [host.example.com] ERROR - a message
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
a message
an error
<BLANKLINE>

You'll notice that the ``%(line)`` substitution inserts the first line
of the whole summary mail when used with a :class:`SummarisingLogger`.

You'll also notice that the ``%(levelname)`` substitution inserts the
name of the highest level logged while the :class:`SummarisingLogger`
was active.

If no messages have been handled by the logger, then ``%(levelname)s``
will be the string ``NOTSET``:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             subject='[%(levelname)s] summary')
>>> logger.addHandler(handler)
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: [NOTSET] summary
To: to@example.com
X-Log-Level: NOTSET
X-Mailer: MailingLogger...
<BLANKLINE>
<BLANKLINE>

Formatting messages in the body of the summary email
----------------------------------------------------

You may also be wondering how you control the formatting of the
messages included in the summary email. This is done using the
standard :meth:`~logging.Handler.setFormatter` method of python log
handlers.

Here's an example:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',))
>>> handler.setFormatter(logging.Formatter('%(asctime)s [%(levelname)s] %(message)s'))
>>> logger.addHandler(handler)

To show things working, some entries need to be logged. Here's one at
``2007-01-01 10:00:00``:

.. 
  >>> time.set(2007, 1, 1, 10)  

>>> logging.warning('something happened')

Here's another at ``2007-01-01 12:34:56``:

.. 
  >>> time.set(2007, 1, 1, 12, 34, 56)  

>>> try:
...   raise RuntimeError('badness')
... except:
...   logging.error('bad things happened',exc_info=True)

The following shows the mail that would be sent:

>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
2007-01-01 10:00:00,000 [WARNING] something happened
2007-01-01 12:34:56,000 [ERROR] bad things happened
Traceback (most recent call last):
...
RuntimeError: badness
<BLANKLINE>

.. _record-and-send-different:

Recording and sending at different levels
-----------------------------------------

In some circumstances, you may want to send a summary email when a
certain log level is reached but, when the summary is sent, you want
the summary to include logging at a lower level. To do this, you would
pass a ``send_level`` to the :class:`SummarisingLogger` constructor:

>>> handler = SummarisingLogger('from@example.com', ('to@example.com',), 
...                             send_level=logging.ERROR)
>>> handler.setFormatter(logging.Formatter('%(asctime)s [%(levelname)s] %(message)s'))
>>> logger.addHandler(handler)
>>> logging.info('An info message')
>>> logging.error('Something bad happened')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: Mon, 01 Jan 2007 12:34:56 -0000
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
2007-01-01 12:34:56,000 [INFO] An info message
2007-01-01 12:34:56,000 [ERROR] Something bad happened
<BLANKLINE>

Limiting the size of emails
---------------------------

All good MTAs will limit the size of message that they will accept. If
your script logs an unexpectedly large number of messages, such as
when something goes catastrophically wrong, this may result in no email
notification being sent.

More commonly, if you're trying to read a summary email on a mobile
device, any more than a hundred lines or so will likely be difficult
to read and may not even render.

To prevent these problems, :class:`SummarisingLogger` allows a limit
on the number of lines that will be included in the summary email.
By default, this is set to 100 messages but can be overridden by passing
the `flood_level` option to the :class:`SummarisingLogger`
constructor:

>>> handler = SummarisingLogger('from@example.com', ('to@example.com',), 
...                             flood_level=2)
>>> handler.setFormatter(logging.Formatter('%(levelname)s -  %(message)s'))
>>> logger.addHandler(handler)
>>> logging.info('message 1')
>>> logging.info('message 2')
>>> logging.error('message 3')
>>> logging.info('message 4')
>>> logging.info('message 5')
>>> logging.info('message 6')
>>> logging.info('message 7')
>>> logging.info('message 8')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: Mon, 01 Jan 2007 12:34:56 -0000
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
INFO -  message 1
INFO -  message 2
CRITICAL -  1 messages not included as flood limit of 2 exceeded
INFO -  message 4
INFO -  message 5
INFO -  message 6
INFO -  message 7
INFO -  message 8
<BLANKLINE>

The example above shows a few things. Firstly, when messages are
excluded, a ``CRITICAL`` entry is logged with the number of messages
that have been excluded. Secondly, excluded messages still contribute
to the highest level logged used in both the subject and the
``X-Log-Level`` header. Finally, the last 5 messages logged before the
mail is sent are always included as they may well contain useful
information such as a terminal exception or total run time.

Sending empty emails
--------------------

By default, the :class:`SummarisingLogger` handler will always send emails
even if they would have been empty: 

>>> handler = SummarisingLogger('from@example.com',('to@example.com',))
>>> logger.addHandler(handler)
>>> logging.error(' ')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
<BLANKLINE>
<BLANKLINE>

Sending empty emails is helpful for batch processes as even if no
activity is logged, the mail itself is an indication that the batch
process did at least run.

However, if you do not want empty entries to be mailed, all you need
to do is supply the `send_empty_entries` parameter:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                         send_empty_entries=False)
>>> logger.addHandler(handler)
>>> logging.error(' ')
>>> logging.shutdown()

Specifying the host to send email through
-----------------------------------------

By default, as we've seen above, :class:`SummarisingLogger` uses localhost
to send mails. If you wish to use a specific smtp server to send
mail, this can be done by specifying the `mailhost` parameter to the
:class:`SummarisingLogger` constructor:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                         mailhost='smtp.example.com')
>>> logger.addHandler(handler)
>>> logging.error('An Error')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('smtp.example.com', 25)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
An Error
<BLANKLINE>

If the smtp server you wish to use is running on non-standard port,
you can configure :class:`SummarisingLogger` to use this port by specifying
`mailhost` as a tuple containing the smtp server's hostname and the
port on which it is listening:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             mailhost=('smtp.example.com',2500))
>>> logger.addHandler(handler)
>>> logging.error('An Error')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('smtp.example.com', 2500)
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
An Error
<BLANKLINE>

If the smtp server you wish to use requires authentication,
pass the required username and password to the :class:`SummarisingLogger`
constructor: 

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             username='auser',password='theirpassword')
>>> logger.addHandler(handler)
>>> logging.error('An Error')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
(authenticated using username:'auser' and password:'theirpassword')
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
An Error
<BLANKLINE>

.. warning::

  For performance reasons, it's recommended that you don't use SMTP
  authentication unless you absolutely need to.


If the smtp server you wish to use requires TLS (Transport Level Security),
pass the required username and password and the secure parameter to the
:class:`SummarisingLogger` constructor. ``secure`` must be either a boolean
or an :class:`ssl.SSLContext` object:

.. invisible-code-block: python

  logging.getLogger('').removeHandler(handler)

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                         username='auser',password='apassword',
...                         secure=True)
>>> logger.addHandler(handler)
>>> logging.error('An Error')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
(authenticated using username:'auser' and password:'apassword')
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger...
<BLANKLINE>
An Error
<BLANKLINE>

.. _sum_extra_headers:

Adding extra headers
--------------------

If you wish to add headers for filtering purposes, you can use the
headers parameter:

>>> handler = SummarisingLogger('from@example.com',('to@example.com',),
...                             headers={'foo':'bar','Baz':'bob'})
>>> logger.addHandler(handler)

Now, when a log message results in an email being send, the email will
be sent with the configured headers:

>>> logging.error('The Error!')
>>> logging.shutdown()
sending to ('to@example.com',) from 'from@example.com' using ('localhost', 25)
Baz: bob
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset="us-ascii"
Date: ...
From: from@example.com
MIME-Version: 1.0
Message-ID: <...MailingLogger@...>
Subject: Summary of Log Messages (ERROR)
To: to@example.com
X-Log-Level: ERROR
X-Mailer: MailingLogger ...
foo: bar
<BLANKLINE>
The Error!
<BLANKLINE>