Is there a better way than using decorators to log output from a function without editing it?

Question

Okay. So, my question might be a bit vague. Here is what I want to do:

I have 'inherited' a large number of python scripts and I am supposed to debug,document and improve them. There isn't a whole lot of documentation available. In almost all cases I know what the input data and output data needs to be.

My plan is to wrap the original functions around a decorator function and log the output in a text file, while not interrupting the normal program flow. I also don't want to mess with the original source code for the time being. So, here is my code for the decorator:

def printoutput(func):
"""Decorator function to write the values of a function to a log file
    1. If the output is a tuple or a list then the output will get written as Output1: .. , Output2:.. etc.
    2. If the output is anything else, it will get written once.
"""

import time

#Accesfunc passes arguments to a calls the actual function. It also logs data.
 def accessfunc(*args,**kwargs):
    #Call the function with any number of arguments and keyword arguments.
    y = func(*args,**kwargs) 

    #Save the name of the function being called.
    funcname = r"D:\{}_{}_output.txt".format(time.time(), func.__name__)

    #Create a file for logging data, specific to a function.
    with open(funcname,'w') as fileoutput:

        #if the output returned by the function is a lsit or tuple then log those on separate lines.
        if isinstance(y,(tuple,list)):
            for idx,outputs in enumerate(y):
                fileoutput.write("Output{}:".format(idx))
                fileoutput.write(str(outputs)+"\n")

        #if the output is a single entity like a string or a number then log it on a single line.
        else:
                fileoutput.write("Output:\n")
                fileoutput.write(str(y))
    return y
 return accessfunc

My questions are:

1. Is there a better way to accomplish what I am trying to do ?

2. I am logging the name of the function, is there a way that I could also log the name of the variables being returned. For example if function A returns B, can I log it in such a way that both "A" and "B" get mentioned in my log file ?

Answer 1

There's sys.settrace which can show you a lot of what's going on without have to modify anything.

http://pymotw.com/2/sys/tracing.html

Here's a slight modification of one of their examples, which grabs locals from the stack frame before the function is executed, which contains the arguments.

import sys

def trace_calls_and_returns(frame, event, arg):
    co = frame.f_code
    func_name = co.co_name
    if func_name == 'write':
        # Ignore write() calls from print statements
        return
    line_no = frame.f_lineno
    filename = co.co_filename
    if event == 'call':
        print 'Call to %s(%s) on line %s of %s' % (func_name, frame.f_locals, line_no, filename)
        return trace_calls_and_returns
    elif event == 'return':
        print '%s() => %s' % (func_name, arg)
    return

def times(a,b):
    foo = "what"
    return a*b

def x(a):
    return times(a,a)

def y(a):
    return times(a,2)

sys.settrace(trace_calls_and_returns)
foo=x(x(y(x(2))))

And the output:

Call to x({'a': 2}) on line 24 of C:/Users/cjd/Desktop/dfdfdfdf.py
Call to times({'a': 2, 'b': 2}) on line 20 of C:/Users/cjd/Desktop/dfdfdfdf.py
times() => 4
x() => 4
Call to y({'a': 4}) on line 27 of C:/Users/cjd/Desktop/dfdfdfdf.py
Call to times({'a': 4, 'b': 2}) on line 20 of C:/Users/cjd/Desktop/dfdfdfdf.py
times() => 8
y() => 8
Call to x({'a': 8}) on line 24 of C:/Users/cjd/Desktop/dfdfdfdf.py
Call to times({'a': 8, 'b': 8}) on line 20 of C:/Users/cjd/Desktop/dfdfdfdf.py
times() => 64
x() => 64
Call to x({'a': 64}) on line 24 of C:/Users/cjd/Desktop/dfdfdfdf.py
Call to times({'a': 64, 'b': 64}) on line 20 of C:/Users/cjd/Desktop/dfdfdfdf.py
times() => 4096
x() => 4096
Call to flush_stdout({}) on line 219 of C:\Python27\lib\idlelib\run.py
flush_stdout() => None
Call to put({'item': (119, None), 'self': <Queue.Queue instance at 0x0000000002B42AC8>, 'block': True, 'timeout': None}) on line 107 of C:\Python27\lib\Queue.py
Call to _put({'item': (119, None), 'self': <Queue.Queue instance at 0x0000000002B42AC8>}) on line 204 of C:\Python27\lib\Queue.py

Answer 2

In my situation, decorator is used for cache or convenience.

For logging, the build-in logging for python is convenient enough.

1. config logging

   logging.config.dictConfig(config.LOGGING)
   

   config.LOGGING is something like: Python Logging Config

2. use logging

   import logging
   
   logger = logging.getLogger(__name__)
   
   logger.info('This is a info log.')
   

In my opinion, log should exist within your codes, it's a kind of record, and it should be explicit as Python-Zen says. So I don't suggest decorators for logging.