Useful Python decorators for logging and text encoding
#1
I recently started using Python decorators in my add-on, and I wanted to share some of the code snippets in case anyone else finds them useful.  If you haven't used decorators yet, they're basically just functions with a special syntax that let you modify other functions by adding code before/after each call and also let you modify the function arguments.

The first decorator logs every call to a function, including the arguments and return values.  The function call in the log also includes the module name, or just the class name if it's a method.  If the return value is an iterable (like a list), it limits the log output to the first five values.

python:
import xbmc
import xbmcaddon

addon = xbmcaddon.Addon()
STR_ADDON_NAME = addon.getAddonInfo('name')
STR_ADDON_VER = addon.getAddonInfo('version')

def log_msg(msg, loglevel=xbmc.LOGNOTICE):
    ''' log message with addon name and version to kodi log '''
    if isinstance(msg, unicode):
        msg = msg.encode('utf-8')
    xbmc.log("{0} v{1} --> {2}".format(STR_ADDON_NAME, STR_ADDON_VER, msg), level=loglevel)

def log_decorator(func):
    ''' decorator for logging function call and return values '''
    def wrapper(*args, **kwargs):
        ''' function wrapper '''
        # call the function and get the return value
        ret = func(*args, **kwargs)
        # define the string for the function call (include class name for methods)
        is_method = hasattr(args[0].__class__, func.__name__)
        parent = args[0].__class__.__name__ if is_method \
            else func.__module__.replace('resources.lib.', '')
        func_str = '{0}.{1}'.format(parent, func.__name__)
        # pretty formating for argument string
        arg_list = list()
        for arg in args[1 if is_method else 0:]:
            arg_list.append("'{0}'".format(arg) if isinstance(arg, basestring) else str(arg))
        for k, v in kwargs.iteritems():
            arg_list.append('{0}={1}'\
                .format(k, "'{0}'".format(v) if isinstance(v, basestring) else str(v)))
        arg_str = '({0})'.format(', '.join(arg_list))
        # add line breaks and limit output if ret value is iterable
        try:
            ret_list = ['\n'+str(x) for x in ret[:5]]
            if len(ret) > 5:
                ret_list += ['\n+{0} more items...'.format(len(ret)-5)]
            ret_str = str().join(ret_list)
        except TypeError:
            ret_str = str(ret)
        # log message at default loglevel
        message = '{0}{1}: {2}'.format(func_str, arg_str, ret_str)
        log_msg(message)
        # return ret value from wrapper
        return ret
    return wrapper

Example log output:

Code:
20:40:54.848 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> DB_Handler.update_content_status('plugin://plugin.video.crackle/?id=2537&mode=103&type=movies', 'staged'): None
20:40:54.849 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> DB_Handler.get_content_items(status='managed', mediatype='movie'): 
                                            30 Minutes Or Less - plugin://plugin.video.crackle/?id=3133&mode=103&type=movies
                                            6 Bullets - plugin://plugin.video.crackle/?id=2449&mode=103&type=movies
                                            Airheads - plugin://plugin.video.crackle/?id=2975&mode=103&type=movies
                                            American Crude - plugin://plugin.video.crackle/?id=1555&mode=103&type=movies
                                            Angel of Death - plugin://plugin.video.crackle/?id=633&mode=103&type=movies
                                            +119 more items...
20:41:01.586 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> DB_Handler.get_content_items(status='staged', mediatype='movie'): 
                                            30 Days of Night: Dark Days - plugin://plugin.video.crackle/?id=2537&mode=103&type=movies
20:41:03.612 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> DB_Handler.update_content_status('plugin://plugin.video.crackle/?id=2537&mode=103&type=movies', 'managed'): None
20:41:03.617 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> utils.notification('All movies added'): None
20:41:06.587 T:123145517723648  NOTICE: Library Integration Tool v0.2.2 --> DB_Handler.get_all_shows('managed'): 
                                            Another Period
                                            Broad City
                                            Corporate
                                            The Daily Show with Trevor Noah
                                            Detroiters
                                            +9 more items...

The other decorator forces all function arguments that are strings to be encoded as utf-8.  I use this on all of my methods that query or update my SQLite database, and I haven't had any text encoding issues since.

python:
def utf8_decorator(func):
    ''' decorator for encoding utf8 on all unicode arguments '''
    def wrapper(*args, **kwargs):
        ''' function wrapper '''
        new_args = (x.encode('utf-8') if isinstance(x, unicode) else x for x in args)
        new_kwargs = {k: v.encode('utf-8') if isinstance(v, unicode) else v \
            for k, v in kwargs.iteritems()}
        return func(*new_args, **new_kwargs)
    return wrapper

These decorators have really helped clean up my code.  I've been able to remove most of the basic log statements, and now text encoding doesn't clutter up my functions any more.  In case you haven't used decorators in Python yet, here is how you would call them on a function:

python:
   @utf8_decorator
    @log_decorator
    def add_synced_dir(self, label, path, mediatype):
        ''' Create an entry in Synced with specified values '''
        self.c.execute(\
            "INSERT OR IGNORE INTO Synced (Directory, Label, Type) VALUES (?, ?, ?)",\
            (path, label, mediatype))
        self.db.commit()
Reply
#2
I don't like to rain on your parade, but still. The 1-st decorator introduces significant overhead that may not be necessary. Python is not a fast language by nature, so you shouldn't over-complicate your code. The 2-nd one is written by a person who obviously does not understand the difference between textual (unicode) and byte strings. BTW, the same encode function in the 1-st decorator is written correctly (borrowed from somewhere?).
Reply
#3
Thanks for the feedback. I'm happy to discuss the code.

I wouldn't say the overhead on the log decorator is significant. It has a slightly complicated control flow, but it runs in constant time (other than when lists are passed as arguments, which I should fix). During development I've stress tested this decorator on most functions/methods and I don't notice any practical slowdown at all. All decorators have some overhead, but you have to use your judgement and not use this for something like DSP. Obviously there's a bit of log spam, so you wouldn't indiscriminately use this in a release version (especially at log level notice) anyways.

One of the ideas I've had for removing overhead is to add a conditional check to only log the call if the Kodi setting for full debug logs is enabled. However I don't see an easy way to access that setting from the xbmc module. If anyone knows if that's possible, I'd be grateful for the help.

As for the text encoding, it seems just checking for unicode like in log_msg does indeed work (and yes that was borrowed).  I’ve tried this in the past and still got errors occasionally, but now it passed my regression tests just fine.  There may have been some other issue in the pipeline that caused my problems in the past.  I’ll update the decorator.
Reply

Logout Mark Read Team Forum Stats Members Help
Useful Python decorators for logging and text encoding0