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']

Solution 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.

Solution 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.

Solution 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.

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

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

View more solutions

Comments

[Will S]

The docs are kind of wordy with regards to this. I had missed that, thanks!

[Scott Stafford]

All parameters are documented here: docs.python.org/2/library/logging.html#logrecord-attributes.

[Erik Aronesty]

hard part is getting the stack_trace[:-1]

[Duncan]

@ErikAronesty, yes and that was already sufficiently covered by other answers when I posted, so I didn't include it in mine.

[ShadowRanger]

Instead of doing stack_trace[:-1] (which means it needs to format one frame more than you use, then slice the result), couldn't you do: frame = inspect.currentframe(1) so you get the stack without the top layer, so format_stack doesn't need to process it, and the return from format_stack requires no manipulation?