28

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

8 Answers 8

22

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.

Sign up to request clarification or add additional context in comments.

3 Comments

hard part is getting the stack_trace[:-1]
@ErikAronesty, yes and that was already sufficiently covered by other answers when I posted, so I didn't include it in mine.
19
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.

1 Comment

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?
19

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.

1 Comment

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

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)

Comments

3

Use the traceback module.

logging.error(traceback.format_exc()) 

Comments

3

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

Comments

1

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 

Comments

1

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

Comments

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.