Log stack trace for python warning

It's a little hackish, but you can monkeypatch the warnings.warn method to this:

import traceback import warnings def g(): warnings.warn("foo", Warning) def f(): g() warnings.warn("bar", Warning) _old_warn = warnings.warn def warn(*args, **kwargs): tb = traceback.extract_stack() _old_warn(*args, **kwargs) print("".join(traceback.format_list(tb)[:-1])) warnings.warn = warn f() print("DONE") 

This is the output:

/tmp/test.py:14: Warning: foo _old_warn(*args, **kwargs) File "/tmp/test.py", line 17, in <module> f() File "/tmp/test.py", line 8, in f g() File "/tmp/test.py", line 5, in g warnings.warn("foo", Warning) /tmp/test.py:14: Warning: bar _old_warn(*args, **kwargs) File "/tmp/test.py", line 17, in <module> f() File "/tmp/test.py", line 9, in f warnings.warn("bar", Warning) DONE 

See that calling the original warnings.warn function does not report the line you'd want, bu the stack trace is indeed correct (you could print the warning message yourself).

If you do not know what data/instruction is causing the warning throw, you can use tools like the standard Python Debugger.

The documentation is really good and detailed, but some quickly examples that may help should be:

• Without modifying source code: invoking the debbugger as script:

  $ python -m pdb myscript.py

• Modifying source code: you can make use of calls to pdb.set_trace(), that work like breakpoints; For example, consider I have the following example code:

  x = 2 x = x * 10 * 100 y = x + 3 + y return y

  And I would like to know what value does x and y have before the return, or what does the stack contains, I would add the following line between those statements:

  pdb.set_trace()

  And I will be promted to the (Pdb) prompt, that will allow you to go through the code line by line. Useful commands for the (Pdb) prompt are:

  • n: executes the next statement.
  • q: quits the whole program.
  • c: quits the (Pdb) prompt and stops debugging.
  • p varname: prints the value of varname

As you do not provide more information, I do not know if that should be enough, but I think that at least, it may be a good start.

BONUS EDIT

Based on this answer, I have found there is a nice and friendly GUI debugging tool, that you can simply install by:

$ pip install pudb

And run the debugger with your script with:

$ python -m pudb.run myscript.py

EDIT: Adding the postmortem debugging

If we do not even know if the code is going to crash or not, we can enter in postmortem debugging if there has been a crash. From the Pbd documentation:

The typical usage to inspect a crashed program is:

>>> import pdb >>> import mymodule >>> mymodule.test() Traceback (most recent call last): File "<stdin>", line 1, in ? File "./mymodule.py", line 4, in test test2() File "./mymodule.py", line 3, in test2 print spam NameError: spam >>> pdb.pm() > ./mymodule.py(3)test2() -> print spam (Pdb) 

As postmortem looks at sys.last_traceback, to enter only if there is a traceback (and so on, a warning or crash):

if sys.last_traceback: pdb.pm() 

You can turn warnings into exceptions, which means you will get a stack trace automatically:

warnings.filterwarnings("error") 

See https://docs.python.org/3.4/library/warnings.html#the-warnings-filter

If it was me, I'd go with @Lluís Vilanova's quick & dirty hack, just to find something. But if that's not an option...

If you really want a "logging" solution, you could try something like this (fully working source).

Basic steps are:

• Create a custom logging.Formatter subclass that includes the current stack where the logging record is formatted
• Use that formatter on the class of the warning

The meat of the code is the custom formatter:

class Formatter(logging.Formatter): def format(self, record): record.stack_info = ''.join(traceback.format_stack()) return super().format(record) 

Per the docs:

New in version 3.2: The stack_info parameter was added. 

For python 3.2 and above, using the optional stack_info keyword argument is the easiest way to get stack trace info along with the log message. In the example below, "Server.py" is using "lib2.py", which is in turn using "lib.py". On enabling the stack_info argument the complete trace back is logged along with every logging.log() call. This works the same with logging.info() and other convenience methods as well.

Usage :-

logging.log(DEBUG, "RWL [{}] : acquire_read()".format(self._ownerName), stack_info=True) 

Output :-

2018-10-06 10:59:55,726|DEBUG|MainThread|lib.py|acquire_read|RWL [Cache] : acquire_read() Stack (most recent call last): File "./Server.py", line 41, in <module> logging.info("Found {} requests for simulation".format(simdata.count())) File "<Path>\lib2.py", line 199, in count with basics.ReadRWLock(self.cacheLock): File "<Path>\lib.py", line 89, in __enter__ self.rwLock.acquire_read() File "<Path>\lib.py", line 34, in acquire_read logging.log(DEBUG, "RWL [{}] : acquire_read()".format(self._ownerName), stack_info=True)