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

Question

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.

Curiel

You can drop into the python debugger by using import pdb; pdb.set_trace(), and then step through code interactively. That may help you trace program flow. – Perice

Great idea! Thanks Matt. It would still be helpful to get a log as mentioned in the question so that I don't have to debug every time. Also, do you know of an IDE for python which is as good as Eclipse for Java (ctrl+click takes you to function definition) that I can make use of to make debugging easier ? – Curiel

What is the question here? – Amanita

Anyone visiting this question in 2022 and beyond... dont use pdb. Its a fine library if the only IDE you have is vim, but if you have a modern IDE such as VSCode or Pycharm, the debugging suites there are more than capable of providing this information without littering your code with unnecessary lines that could potentially be a source of problems if left in. – Ochlophobia

Answer 1

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.

Perice

Thanks Matt ! I will try this autolog function. I have a little confusion regarding the using dict as RHS of % operator: Would '%(foo)s : %(bar)s' would also print the bar["foo"]'s value ? Or is it somewhat different than your example ? – Curiel

Basically, everything of the form %(<foo>)s is replaced by the value of the object referenced in the dict by <foo>. There are more examples/detail at docs.python.org/library/stdtypes.html#string-formatting – Perice

@Baywood 's answer is much more helpful. – Huddle

Answer 2

The correct answer for this is to use the already provided funcName variable

import logging
logger = logging.getLogger(__name__)
FORMAT = "[%(filename)s:%(lineno)s - %(funcName)20s() ] %(message)s"
logging.basicConfig(format=FORMAT)
logger.setLevel(logging.DEBUG)

Then anywhere you want, just add:

logger.debug('your message') 

Example output from a script I'm working on right now:

[invRegex.py:150 -          handleRange() ] ['[A-Z]']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03050>, '{', '1', '}']]
[invRegex.py:197 -          handleMacro() ] ['\\d']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03950>, '{', '1', '}']]
[invRegex.py:210 -       handleSequence() ] [[<__main__.GroupEmitter object at 0x10b9fedd0>, <__main__.GroupEmitter object at 0x10ba03ad0>]]

Baywood

Great.. One thing to add, can we name the logfile to be same as codefile dynamically? eg: I tried logging.basicConfig(filename= "%(filename)", format=FORMAT) to take filename dynamically, but it took static value. any suggestion? – Jaynajayne

@Outlier No, the recommended way to achieve that is via getLogger(__name__) – Lint

I have one question: In Java somewhere I read that printing the line number is discouraged as it takes extra time to figure out from which line the logger is being called. In python this isn't true? – Waldrop

how can i also put the caller in the FORMAT? – Mirtamirth

Irrelevant, but logging.getLogger('root') isn't what you're expecting probably, it's not the root logger, but an ordinary logger with name 'root'. – Sound

Recommend updating answer to link to docs.python.org/3/library/logging.html#logrecord-attributes for viewing all available placeholders. – Recapitulate

Accept this please – Cheng

What does 20s() in %(funcName)20s() do? – Ungenerous

@Ungenerous I think it formats 20 spaces, right justified. – Baywood

Answer 3

I like the answer given by @synthesizerpatel but I like this format better to include the level name

FORMAT = "[%(asctime)s %(filename)s->%(funcName)s():%(lineno)s]%(levelname)s: %(message)s"
logging.basicConfig(format=FORMAT, level=logging.INFO)

Results in something like:

[2022-04-25 11:00:50,885 main.py->loop():21]INFO: looping

For point 3, you can log to a file using filename in the basic config:

logging.basicConfig(format=FORMAT, level=logging.INFO, filename='main.log')

but I prefer to setup a rotating log file so it doesn't grow uncontrolled with RotatingFileHandler. It will also show up in the console at the same time as writing to the log file

Full example main.py

import logging                                                                                         
from logging.handlers import RotatingFileHandler                                                       
import time                                                                                            
                                                                                                       
#Setup logger                                                                                          
logger = logging.getLogger(__name__)                                                                   
FORMAT = "[%(asctime)s %(filename)s->%(funcName)s():%(lineno)s]%(levelname)s: %(message)s"             
logging.basicConfig(format=FORMAT, level=logging.INFO)                                                 
#Log to file                                                                                           
logging_filename = 'main.log'                                                                          
handler = RotatingFileHandler(logging_filename, maxBytes=1000000, backupCount=10) #10 files of 1MB each
handler.setFormatter(logging.Formatter(FORMAT))                                                        
logger.addHandler(handler)                                                                             
                                                                                                       
def main():                                                                                            
  while True:                                                                                        
    loop()                                                                                         
    time.sleep(1)                                                                                  
                                                                                                       
def loop():                                                                                            
  logger.info('looping')                                                                             
                                                                                                       
if __name__== "__main__":                                                                              
  main()                                                                                               
                                                                                                       

Fatsoluble

Answer 4

funcname, linename and lineno provide information about the last function that did the logging.

If you have wrapper of logger (e.g singleton logger), then @synthesizerpatel's answer might not work for you.

To find out the other callers in the call stack you can do:

import logging
import inspect

class Singleton(type):
    _instances = {}

    def __call__(cls, *args, **kwargs):
        if cls not in cls._instances:
            cls._instances[cls] = super(Singleton, cls).__call__(*args, **kwargs)
        return cls._instances[cls]

class MyLogger(metaclass=Singleton):
    logger = None

    def __init__(self):
        logging.basicConfig(
            level=logging.INFO,
            format="%(asctime)s - %(threadName)s - %(message)s",
            handlers=[
                logging.StreamHandler()
            ])

        self.logger = logging.getLogger(__name__ + '.logger')

    @staticmethod
    def __get_call_info():
        stack = inspect.stack()

        # stack[1] gives previous function ('info' in our case)
        # stack[2] gives before previous function and so on

        fn = stack[2][1]
        ln = stack[2][2]
        func = stack[2][3]

        return fn, func, ln

    def info(self, message, *args):
        message = "{} - {} at line {}: {}".format(*self.__get_call_info(), message)
        self.logger.info(message, *args)

Ichnology

Your answer was exactly what I needed to solve my problem. Thank you. – Dorise

Since Python 3.8, the logging class supports stack level skipping out-of-the-box: methods like log(), debug(), etc. now accept a stacklevel argument. See the docs. – Biome