App specific logging in Transifex

Yesterday, I was working on adding app specific loggers in Transifex. By app specific logger I mean a logger which shows the app name which generated the log. As of now, the logs in Transifex look something like this:


2012-06-29 13:01:43,300 tx DEBUG Saved: Project Avant Window Navigator
2012-06-29 13:01:43,312 tx DEBUG Saved: Project Switchdesk
2012-06-29 13:01:43,324 tx DEBUG Saved: Project Usermode
2012-06-29 13:01:43,342 tx DEBUG Saved: Project desktop-effects
2012-06-29 13:01:43,349 tx DEBUG Saved: Project im-chooser
2012-06-29 13:01:43,355 tx DEBUG Saved: Project Test Project
2012-06-29 13:01:43,364 tx DEBUG Saved: Project Test Private Project
2012-06-29 13:01:45,704 tx DEBUG Saved: Project Test Project
2012-06-29 13:01:45,717 tx DEBUG Saved: Project Test Private Project
2012-06-29 13:01:45,731 tx DEBUG Resource Resource1: New ResourcePriority created.

It does not tell anything about which app generated the logs. In a first glance, fixing this looks pretty straight forward and dumb. All it needs it to customize this https://github.com/transifex/transifex/tree/devel/transifex/txcommon/log module for each app and instead of importing the logger from txcommon.log, import it from the log module inside the app.
But this would lead to a lot of code duplication and a lot of boring changes in the code. So, I decided to customize transifex.txcommon.log module itself so that it can detect the function calling the logger. It was pretty straight forward to do this for the handler at https://github.com/transifex/transifex/blob/devel/transifex/txcommon/log/receivers.py#L6: def model_named() in the following way:

import re

tx_module_regex = re.compile(
    r'transifex(\.addons)?\.(?P<app_name>\w+)(\..*)?')
def model_named(sender, message='', **kwargs):
    """
    Receive signals for objects with a .name attribute.
    """
    from txcommon.log import _logger as logger
    sender_module = sender.__module__
    m = tx_module_regex.search(sender_module)
    app_name = '.' + m.group('app_name') if m else ''
    logger.name = 'tx' + app_name
    obj = kwargs['instance']
    logger.debug("%(msg)s %(obj)s %(name)s" %
            {'msg': message,
            'obj': sender.__name__,
            'name': getattr(obj, 'name', '')})

sender is the object or instance for which the log is being generated. In our case, it’s a model instance. So, sender.__module__ gives the parent module for sender. Using regular expressions, we extract the app name from the module name and we set the name of the logger as ‘tx.<app_name>‘. And we are done here (for now)! But when we do something like

from transifex.txcommon.log import logger
logger.debug('foo bar')

we do not have a sender instance to allow us to find the calling module name. After some searching, I found about the inspect python module. And all I needed was inspect.stack(). Here’s what I did in https://github.com/transifex/transifex/tree/devel/transifex/txcommon/log/__init__.py:

  1. Write a wrapper around logger instance,
  2. find the caller calling the logger using stack.inspect(),
  3. accordingly set the logger name,
  4. and finally, log the event.

import logging, re, inspect

_logger = logging.getLogger('tx')

# regex to extract app name from a file path to a TXC app
tx_app_path_regex = re.compile(
r'txc/transifex(/addons)?/(?P<app_name>\w+)/(\..*)?')
class Logger:
    """
    A wrapper class around _logger. This is used to log events
    along with app names.
    """
    @classmethod
    def get_app_name_from_path(cls, path):
        """
        Extracts app name from a file path to a TXC app

        Args:
            path: A string for the file path
        Returns:
            A string for the app name or ''
        """
        m = tx_app_path_regex.search(path)
        return m.group('app_name') if m else ''

    @classmethod
    def set_logger_name(cls):
        """
        Sets logger name to show calling app's name.
        """
        # inspect.stack()[2] since cls.debug() method has now become the
        # immediate caller in of this method in the stack. We want the caller
        # of cls.debug() or other logging method wrappers.
        caller_module_path = inspect.stack()[2][1]
        app_name = cls.get_app_name_from_path(caller_module_path)
        _logger.name = 'tx' + '.%s' % app_name if app_name else ''

    @classmethod
    def debug(cls, *args, **kwargs):
        """Wrapper for _logger.debug"""
        cls.set_logger_name()
        _logger.debug(*args, **kwargs)

    # And similarly for other logger methods like info(), waring(), error(), critical()

logger = Logger

Now, this is sweet! No one need to bother about logging events with app names. I am saved from editing hundreds of files and duplicating code 😉 It’s transparent and scalable. The logs now seem like:

2012-06-29 20:39:03,635 tx.projects DEBUG Saved: Project Foo Project
2012-06-29 20:39:05,575 tx.projects DEBUG Saved: Project Avant Window Navigator
2012-06-29 20:39:05,587 tx.projects DEBUG Saved: Project Switchdesk
2012-06-29 20:39:05,599 tx.projects DEBUG Saved: Project Usermode
2012-06-29 20:39:05,612 tx.projects DEBUG Saved: Project desktop-effects
..........
..........
..........
2012-06-29 22:15:07,088 tx.webhooks DEBUG Project project1 has no web hooks
2012-06-29 22:15:07,177 tx.releases DEBUG Deleted: ReleaseNotifications
2012-06-29 22:15:07,177 tx.releases DEBUG Deleted: Release All Resources
2012-06-29 22:15:07,466 tx.txcommon DEBUG Running low-level command 'msgfmt -o /dev/null --check-format --check-domain -'
2012-06-29 22:15:07,469 tx.txcommon DEBUG CWD: '/home/rtnpro/transifex/rtnpro/github/txc/transifex'
2012-06-29 22:15:07,661 tx.releases DEBUG release: Checking string freeze breakage.
2012-06-29 22:15:07,702 tx.resources DEBUG resource: Checking if resource translation is fully reviewed: Test Project: Resource1 (pt_BR)
2012-06-29 22:15:07,707 tx.webhooks DEBUG Project project1 has no web hooks
2012-06-29 22:15:07,740 tx.resources DEBUG resource: Checking if resource translation is fully reviewed: Test Project: Resource1 (ar)
2012-06-29 22:15:07,745 tx.webhooks DEBUG Project project1 has no web hooks

Thanks for reading. If you have any suggestions or query, please feel free to comment.

Advertisements

FUDCON KL Day 3

The 3rd day of FUDCON KL started a bit sluggishly for me. May be because of brainstorming and hacking till late night. We (Kushal, Soumya and me) decided to work on a new app to display system logs in a user friendly manner. We named the application Tower log tower, in short, tlogt, after Twin towers of Kuala Lumpur 😉

During the first few hours of the day, we went to visit some tourist spots in Kuala Lumpur: Aquaria and Petronas towers. After we returned, we settled down for the on going talks. Amidst of various talks on the 3rd day of FUDCON, I was sometimes in listening mode, but for most time I was in coding mode. We decided to try something different in TlogT. The UI would be rendered by a Django daemon with all the WOW factor of HTML, CSS and JS. I was to code the Django server code, while Kushal and Soumya were working on writing the parsers for extracting the logs for various processes. In a few hours, we had a decent Django based functional desktop app ready. Although, quite some work remains to be done on the UI part.

There was Kushal’s session on Python for newbies in the afternoon. It’s always nice to see Kushal talk on Python. I don’t have the exact count, but I am sure that Python sessions by Kushal inspired many (including me and my friends) to start coding in Python. The ending keynote for the day was given by Abu Mansur Manaf. This should really boost newbies to become contributors 🙂

I spent the evening in the hotel room listening about various functional programming languages and features of the languages from hircus and Kushal. Later, we went out for dinner with the rest of the event crew members to a local food joint. I stayed up at night to see off other Kushal, Soumya and others who had to catch an early morning flight back to India. After bidding them good bye, I packed my bags and went to sleep.