How to implement an implicit logger in Python?

Question

I want to add some helpful logging to a Python codebase.

I'm looking to add logging roughly of the form:

[2022-01-06 10:00:01] function foo called with args x=1, y=22, z=3
[2022-01-06 10:00:05] function foo returned 1416
[2022-01-06 10:00:13] function bar called with args w=1416
[2022-01-06 10:00:16] function bar returned None

I could do this by wrapping all functions in the codebase with a decorator, but is there a better way? At least to indicate the timestamp and order in which functions are being called.

I could implement the decorator:

def logthis(func):
    def inner(*args, **kwargs):
        logger.info(f'Calling {func.__name__} with args={args} and kwargs={kwargs}')
        ans = func(*args, **kwargs)
        logger.info(f'Function {func.__name__} returned {ans}')
        return ans
    return inner

@logthis
def foo(x, y, z):
   return x+y+z

@logthis
def bar(w):
   return None

This works reasonably well; provided I'm happy to add it across my whole codebase.

You'd need to explicitly log the parameters and return values, and doing that would naturally be ordered, but timestamp can easily be added - https://docs.python.org/3/howto/logging.html#displaying-the-date-time-in-messages — OneCricketeer, Jan 06 '22 at 22:30
I really want to avoid adding hundreds of lines of code just to log function invocations. I'll keep looking for now. — MYK, Jan 06 '22 at 22:42
Nit: your decorator should return `ans`, not call the function a second time. — chepner, Jan 06 '22 at 23:00
Logging *every single function in your codebase* is going to be massive overhead and not as useful as you're thinking. — user2357112, Jan 06 '22 at 23:01
Yeah, I'm testing it now, at least around the high level entry points. My code is basically a pipeline, so not too worried about the overhead right now. — MYK, Jan 06 '22 at 23:05
You could use [`sys.setrace`](https://docs.python.org/3/library/sys.html#sys.settrace) to trace and log the function calls. There's an example of using it in the article [Tracing a Program As It Runs](https://pymotw.com/3/sys/tracing.html) on the [Python 3 Module of the Week](https://pymotw.com/3/#python-3-module-of-the-week) website. You could make it selective if you wished… — martineau, Jan 07 '22 at 00:09
Also see [How do I print functions as they are called?](https://stackoverflow.com/questions/8315389/how-do-i-print-functions-as-they-are-called) — martineau, Jan 07 '22 at 00:15

score 1 · Answer 1 · edited Jan 07 '22 at 13:47

You can use the inspect module. I typically use it to implement a "Get the filepath of the function that called this function" method I use for various reasons. inspect.stack() (see this) may be what you are looking for as you can go up the list of callers and create info about it.

From there I think the only problem you'd have is how to log the time. Another idea is two create a wrapper for entire classes or a function that you pass __locals__() to that gets all functions and applies a decorator to them. That method is going somewhat into meta programming since you'd have to reconstruct the class objects /update/wrap all of their functions like you have and whatnot, but it could save you a fair amount of tedious work.

Also see the traceback module.

How to implement an implicit logger in Python?

1 Answers1