Python Logging (function name, file name, line number) using a single file

I am trying to learn how an application works. And for this I am inserting debug commands as the first line of each function’s body with the goal of logging the function’s name as well as the line number (within the code) where I send a message to the log output. Finally, since this application comprises of many files, I want to create a single log file so that I can better understand the control flow of the application.

Here is what I know:

1. for getting function name, I can use function_name.__name__ but I don’t want to use the function_name (so that I could rapidly copy and paste a generic Log.info("Message") in the body of all functions). I know this could be done in C using __func__ macro but I am not sure about python.

2. for getting the filename and line number, I have seen that (and I believe that) my application is using Python locals() function but in a syntax that I am not completely aware of e.g.: options = "LOG.debug('%(flag)s : %(flag_get)s' % locals()) and I tried it using like LOG.info("My message %s" % locals()) which produces something like {'self': <__main__.Class_name object at 0x22f8cd0>}. Any input on this please?

3. I know how to use logging and add handler to it to log to a file but I am not sure if a single file can be used to record all log messages in correct order of function calls in the project.

Answer

You have a few marginally related questions here.

I’ll start with the easiest: (3). Using logging you can aggregate all calls to a single log file or other output target: they will be in the order they occurred in the process.

Next up: (2). locals() provides a dict of the current scope. Thus, in a method that has no other arguments, you have self in scope, which contains a reference to the current instance. The trick being used that is stumping you is the string formatting using a dict as the RHS of the % operator. "%(foo)s" % bar will be replaced by whatever the value of bar["foo"] is.

Finally, you can use some introspection tricks, similar to those used by pdb that can log more info:

def autolog(message):
    "Automatically log the current function details."
    import inspect, logging
    # Get the previous frame in the stack, otherwise it would
    # be this function!!!
    func = inspect.currentframe().f_back.f_code
    # Dump the message + the name of this function to the log.
    logging.debug("%s: %s in %s:%i" % (
        message, 
        func.co_name, 
        func.co_filename, 
        func.co_firstlineno
    ))

This will log the message passed in, plus the (original) function name, the filename in which the definition appears, and the line in that file. Have a look at inspect – Inspect live objects for more details.

As I mentioned in my comment earlier, you can also drop into a pdb interactive debugging prompt at any time by inserting the line import pdb; pdb.set_trace() in, and re-running your program. This enables you to step through the code, inspecting data as you choose.