162

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.

4
  • 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. Jun 11, 2012 at 1:17
  • 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 ? Jun 11, 2012 at 3:03
  • 1
    What is the question here? Oct 15, 2022 at 5:59
  • 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.
    – lynkfox
    Nov 2, 2022 at 16:04

4 Answers 4

682

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>]]
9
  • 1
    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?
    – Outlier
    Sep 25, 2014 at 20:41
  • 2
    @Outlier No, the recommended way to achieve that is via getLogger(__name__)
    – farthVader
    Nov 4, 2015 at 2:50
  • 2
    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?
    – McSonk
    Oct 2, 2017 at 3:36
  • 2
    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'.
    – 0xc0de
    Apr 21, 2019 at 6:26
  • 3
    @hipoglucido I think it formats 20 spaces, right justified. Dec 8, 2021 at 23:00
41

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.

3
  • 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 ? Jun 11, 2012 at 14:54
  • 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 Jun 12, 2012 at 2:02
  • 6
    @synthesizerpatel 's answer is much more helpful.
    – Jan
    Jan 3, 2018 at 23:24
9

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)
2
  • 2
    Your answer was exactly what I needed to solve my problem. Thank you. Mar 13, 2019 at 13:50
  • 2
    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.
    – amain
    Apr 22, 2020 at 23:10
9

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()                                                                                               
                                                                                                       

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.