praekelt/vumi — pull request #526 by vgeddes (2013-05-23 23:36:31+00:00)
Title: Logging Improvements

After working with Vumi and Sentry for a bit I came across what I think are some deficiencies in the current logging approach. Apart from making logs less useful, the situation also impacts on well we can utilize Sentry.

### Issues

#### Anonymous, unnamed log statements
Twisted does a pretty bad job of guessing the component which issued a log statement, and even gives the wrong names to loggers.

For example, this message was logged in HeartBeatMonitor.consume_message(), but Twisted can't figure that out:

2013-05-17 02:57:08+0200 [WorkerAMQClient,client] Received message: ...

#### Message severity and worker PID excluded from log files
Even though twisted logging doesn't have severity levels, this still makes it hard to discern between normal messages and errors.

To get around Twisted's lack of levels, I see in Vumi a lot of hardcoding of levels in the messages themselves, for example `log.msg("DEBUG: ...")`.

Including the PID is very useful when you want to grep errors for a worker processed which died sometime in the past.

#### Sentry unable to aggregate errors due to too-early log message formatting
Looking through the Sentry dashboard, I saw many cases where Sentry was unable to aggregate errors which were signalled from exactly the same place in Vumi workers. This clutters up the sentry dashboard and makes it harder to see how many times a particular error was fired.

The fix is to pass the message format and formatting parameters down to the logger. These objects can be passed to the sentry client, so that Sentry can do intelligent grouping of errors.

### New logging system

* Supports legacy logging style out-of-the-box
* Compatible with python 2.5, 2.6

Code: https://github.com/praekelt/vumi/blob/feature/issue-526-improved-sentry-usage/vumi/log.py (most of the heavy lifting has been done, but need to update tests, etc)

#### Setup
As with the legacy logger, just import vumi.log
```python
from vumi import log
```

#### Named Loggers

Helps the issue of trying to troubleshoot workers when the log messages have no context. If you use the default unnamed logger, then we fallback to using Twisted's logger naming mechanism.

```python
log.name('MyObject').info("Hello")
```
Alternatively, when associating static loggers to classes
```python
self.log = log.name(self)
self.log.info("Hello")
```

#### Built-in formatting
We use `%` style formatting since the newer `{}` style is only available in 2.7 and above. By passing on the work of formatting to the logger, we allow Sentry to group errors more intelligently.

```python
log.error("Reached window threshold too early: size=%s", window.size)
```
#### Log levels

```python
log.debug(msg)
log.info(msg)
log.error(msg)
log.critical(msg)
```

#### Support for Exceptions and Twisted Failures

`log.error` will attempt to find an exception in the current scope and will print a Traceback if necessary (as well as pass it on to Sentry).

Alternatively, an explicit error object (such as Exception or twisted.failure.Failure') can be passed to the logger using the `error` keyword argument.

```python
try:
...
except ParseError as ev
log.error("Message parsing failed: client_id=%s", client_id, error=ev)
```

#### Supports Legacy Twisted style formatting

```python
from vumi import log

log.msg("Hello")
log.err(failure, "Failure detected")
```