How can I log current line, and stack info with Python?

Question

I have logging function as follows.

logging.basicConfig(
    filename = fileName,
    format = "%(levelname) -10s %(asctime)s %(message)s",
    level = logging.DEBUG
)

def printinfo(string):
    if DEBUG:
        logging.info(string)

def printerror(string):
    if DEBUG:
        logging.error(string)
    print string

I need to login the line number, stack information. For example:

1: def hello():
2:    goodbye()
3:
4: def goodbye():
5:    printinfo()

---> Line 5: goodbye()/hello()

How can I do this with Python?

SOLVED

def printinfo(string):
    if DEBUG:
        frame = inspect.currentframe()
        stack_trace = traceback.format_stack(frame)
        logging.debug(stack_trace[:-1])
    if LOG:
        logging.info(string)

gives me this info which is exactly what I need.

DEBUG      2011-02-23 10:09:13,500 [
  '  File "/abc.py", line 553, in <module>\n    runUnitTest(COVERAGE, PROFILE)\n', 
  '  File "/abc.py", line 411, in runUnitTest\n    printinfo(string)\n']

Answer 1

Current function name, module and line number you can do simply by changing your format string to include them.

logging.basicConfig(
    filename = fileName,
    format = "%(levelname) -10s %(asctime)s %(module)s:%(lineno)s %(funcName)s %(message)s",
    level = logging.DEBUG
)

Most people only want the stack when logging an exception, and the logging module does that automatically if you call logging.exception(). If you really want stack information at other times then you will need to use the traceback module for extract the additional information you need.

Answer 2

import inspect
import traceback

def method():
   frame = inspect.currentframe()
   stack_trace = traceback.format_stack(frame)
   print ''.join(stack_trace)

Use stack_trace[:-1] to avoid including method/printinfo in the stack trace.

Answer 3

As of Python 3.2, this can be simplified to passing the stack_info=True flag to the logging calls. However, you'll need to use one of the above answers for any earlier version.

Answer 4

Late answer, but oh well.

Another solution is that you can create your own formatter with a filter as specified in the docs here. This is a really great feature as you now no longer have to use a helper function (and have to put the helper function everywhere you want the stack trace). Instead, a custom formatted implements it directly into the logs themselves.

import logging
class ContextFilter(logging.Filter):
    def __init__(self, trim_amount)
        self.trim_amount = trim_amount
    def filter(self, record):
        import traceback
        record.stack = ''.join(
            str(row) for row in traceback.format_stack()[:-self.trim_amount]
        )
        return True

# Now you can create the logger and apply the filter.
logger = logging.getLogger(__name__)
logger.addFilter(ContextFilter(5))

# And then you can directly implement a stack trace in the formatter.    
formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s \n %(stack)s')

Note: In the above code I trim the last 5 stack frames. This is just for convenience and so that we don't show stack frames from the python logging package itself.(It also might have to be adjusted for different versions of the logging package)

Answer 5

Here is an example that i hope it can help you:

import inspect
import logging

logging.basicConfig(
    format = "%(levelname) -10s %(asctime)s %(message)s",
    level = logging.DEBUG
)

def test():

    caller_list = []
    frame = inspect.currentframe()
    this_frame = frame  # Save current frame.

    while frame.f_back:
        caller_list.append('{0}()'.format(frame.f_code.co_name))
        frame = frame.f_back

    caller_line = this_frame.f_back.f_lineno
    callers =  '/'.join(reversed(caller_list))

    logging.info('Line {0} : {1}'.format(caller_line, callers))

def foo():
    test()

def bar():
    foo()

bar()

Result:

INFO       2011-02-23 17:03:26,426 Line 28 : bar()/foo()/test()

Answer 6

Use the traceback module.

logging.error(traceback.format_exc())

Answer 7

This is based on @mouad's answer but made more useful (IMO) by including at each level the filename (but not its full path) and line number of the call stack, and by leaving the stack in most-recently-called-from (i.e. NOT reversed) order because that's the way I want to read it :-)

Each entry has file:line:func() which is the same sequence as the normal stacktrace, but all on the same line so much more compact.

import inspect

def callers(self):
    caller_list = []
    frame = inspect.currentframe()
    while frame.f_back:
        caller_list.append('{2}:{1}:{0}()'.format(frame.f_code.co_name,frame.f_lineno,frame.f_code.co_filename.split("\\")[-1]))
        frame = frame.f_back
    callers =  ' <= '.join(caller_list)
    return callers

You may need to add an extra f_back if you have any intervening calls to produce the log text.

        frame = inspect.currentframe().f_back

Produces output like this:

file2.py:620:func1() <= file3.py:211:func2() <= file3.py:201:func3() <= main.py:795:func4() <= file4.py:295:run() <= main.py:881:main()

I only need this stacktrace in two key functions, so I add the output of callers into the text in the logger.debug() call, like htis:

logger.debug("\nWIRE: justdoit request -----\n"+callers()+"\n\n")

Answer 8

Look at traceback module

>>> import traceback
>>> def test():
>>>     print "/".join( str(x[2]) for x in traceback.extract_stack() )
>>> def main():
>>>     test()
>>> main()
<module>/launch_new_instance/mainloop/mainloop/interact/push/runsource/runcode/<module>/main/test