Pretty logging in Django (part 1)

Who said that logs should be in text format and hard to find? Let’s make a logger that could be accessible through web browser and you wouldn’t have to switch the browser’s tab when you debugging…

Debugging code can be really hard. You have to find a specific corner case that your (or other’s) code didn’t covered. This case is quite easy to reproduce on production environment and quite hard on development environment. Especially when you’re developing cloud-based application when your production data can be measured in giga- or terabytes and you have no idea which of them are responsible for the particular exception.

The best way in that case is to deploy a test version of production code into production environment and reproduce the user-story. When you achieve the problematic situation – you can start debugging.

The most popular way in this case is logging the value of each variable in code responsible for presenting the particular view. But, at least in Google App Engine, you have the following problems:

  • Logging console is in Google panel, so you have to switch between browser’s tabs or windows to make request and read logs
  • Google’s logging console works in real time, so sometimes reading logs can be interrupted by fetching new logs
  • Logging console logs every request – even static, so find a request that you want to debug can be quite hard
  • Last but not least: Google stores only 1 GB of application logs for free. When you’ll logging a lot of data on production – your limit can be exceeded in really short term.

The best solution to avoid all of those inconveniences is to add logs to the frontend view of the application. This allows us also to make them better readable. Ok, let’s start coding 🙂

Frontend Logger

First of all, we have to create a class that will be responsible for logging and presenting logs. Let’s do this in that way:

class FrontendLogger(object):
    entities = []
    request = None

    def __init__(self, request=None):
        self.entities = []
        self.request = request

    def log(self, entity):
        caller = getframeinfo(stack()[1][0])
        self.entities.append((datetime.datetime.now().time(), caller.filename, caller.lineno, entity))

    def html(self):
        if not self.request:
            raise NotImplementedError('You have to setup request in constructor or response')
        html = u'<html><head><title>Debug: %s</title></head>' % self.request.get_full_path()
        html += u'<body><table>'
        for e in self.entities:
            html += u'<tr><td>%(time)s</td>' \
                    u'<td>%(file)s</td>' \
                    u'<td>%(line)s</td>' \
                    u'<td><pre>%(entity)s</pre></td>' \
                    u'</tr>\n' % {'time': e[0],
                                  'file': e[1],
                                  'line': e[2],
                                  'entity': escape(pprint.pformat(e[3]).decode('utf-8'))
                                  }
        html += u'</table></html>'
        return html

    def response(self, request=None):
        if request:
            self.request = request
        return HttpResponse(self.html())

The FrontendLogger object should be initialized with WSGIRequest or, at least, the request should be passed to the response() method.

This class is fully functional logger, but has one very usefulness defect. When you debugging code using this class – all log() executions have to be made on the same object. That means – if you want to log something deeper than inside your view (for example: in method or template tag) you have to transfer the logger object to that particular method. This can be hard and we want to keep logger super-easy to use.

Request Logger

So let’s create another class to avoid this disadvantages:

class RequestLogger(FrontendLogger):
    entities_per_request_id = {}

    def __init__(self):
        self.request = None
        self.entities_per_request_id = {}

    def _set_entities(self, x):
        self.entities_per_request_id[os.environ.get('REQUEST_LOG_ID')] = x

    def _get_entities(self):
        REQUEST_LOG_ID = os.environ.get('REQUEST_LOG_ID')
        try:
            return self.entities_per_request_id[REQUEST_LOG_ID]
        except KeyError:
            self._set_entities([])
            return self.entities_per_request_id[REQUEST_LOG_ID]

    def response(self, *args, **kwargs):
        resp = super(RequestLogger, self).response(*args, **kwargs)
        REQUEST_LOG_ID = os.environ.get('REQUEST_LOG_ID')
        del self.entities_per_request_id[REQUEST_LOG_ID]
        self.request = None
        return resp

    entities = property(_get_entities, _set_entities)

Few words of explanation…

On Google App Engine variable os.environ has a key ‘REQUEST_LOG_ID’, which is unique for each http request. Based on this value we can have objects stored only for request’s lifetime. In this case – we need to store log entities only for this particular request. So all the RequestLogger’s code have to do is to keep log entities separate for each request and clean memory when request ends.

Logger Instance

We want the use logger was very simple. So let’s create one global instance of RequestLogger and use it all our debugging process like this:

from frontend_logger import logger

def my_view(request):
    # some code here....
    logger.log('It works!')
    logger.log(some_object)
    return logger.response(request)

Looks nice? Could be better, right? We will still work on it 🙂

Follow my blog and this project on github.

Leave a Reply

Your email address will not be published. Required fields are marked *

*
*