Log stack trace for python warning

问题:

A package that I'm using in my python program is throwing a warning that I'd like to understand the exact cause of. I've set logging.captureWarning(True) and am capturing the warning in my logging, but still have no idea where it is coming from. How do I also log the stack trace so I can see where in my code the warning is coming from? Do I use traceback?

回答1:

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

回答2:

I've ended up going with the below:

import warnings
import traceback

_formatwarning = warnings.formatwarning

def formatwarning_tb(*args, **kwargs):
    s = _formatwarning(*args, **kwargs)
    tb = traceback.format_stack()
    s += ''.join(tb[:-1])
    return s

warnings.formatwarning = formatwarning_tb
logging.captureWarnings(True)

回答3:

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

回答4:

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

回答5:

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.

回答6:

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)