pkdexc leaves out important information on python 3

[njsmith]

In Python 3, exceptions carry more contextual information than just their traceback. They also have .__context__ and .__cause__ attributes that carry information about other exceptions that may have triggered this one. And then those exceptions might have their own .__context__ and .__cause__. (See PEP 3134 for details.)

This gets even more complex with trio, because you have to handle "exception groups" (when multiple unhandled exceptions are raised simultaneously in different branches of the call tree, and then end up getting grouped together).

Unfortunately, pkdexc doesn't know about any of this stuff: it just formats the latest exception's traceback, and throws away all the contextual information:

pykern/pykern/pkdebug.py

Lines 159 to 165 in 784dded

	try:
	stack = traceback.format_stack()[:-2]
	e = sys.exc_info()
	stack += traceback.format_tb(e[2])
	return ''.join(traceback.format_exception_only(e[0], e[1]) + stack)
	except Exception as e:
	return 'pykern.pkdebug.pkdexc: unable to retrieve exception info'

I think the simplest thing to do on python 3 is to use traceback.format_exceptionwhich does know how to handle all this stuff. For example:

In [2]: try: 
   ...:     try: 
   ...:         raise ValueError 
   ...:     except: 
   ...:         raise RuntimeError 
   ...: except Exception as e: 
   ...:     exc = e                                                             

In [3]: traceback.format_exception(type(exc), exc, exc.__traceback__)           
Out[3]: 
[
    'Traceback (most recent call last):\n',
    '  File "<ipython-input-2-8807d67037fa>", line 3, in <module>\n    '
        'raise ValueError\n',
    'ValueError\n',
    '\nDuring handling of the above exception, another exception '
        'occurred:\n\n',
    'Traceback (most recent call last):\n',
    '  File "<ipython-input-2-8807d67037fa>", line 5, in <module>\n    '
        'raise RuntimeError\n',
    'RuntimeError\n'
]

This does mean we can't as easily graft the current stack onto the exception's stack, like pkdexc does now. But we could print the current stack with a little header like Exception encountered at:\n + current stack + format_exception output.

[robnagler]

Just to be clear for py3 (ignoring py2 case for simplicity):

     e = sys.exc_info() 
     return ''.join(traceback.format_exception_only(e[0], e[1], e[2])

[njsmith]

format_exception_only is just the RuntimeError: your message here part of the string... it's format_exception that handles all the complicated bits.

[robnagler]

Sorry, I meant to write that. :)

[robnagler]

I don't think format_exception works right. The goal of pkdexc is to give the entire context of the error, including the callstack from the point of where pkdexc() is called. This is why pkdexc() is different from just calling print_exception, which only gives the trace up the stack, not down (in py3 as well as py2). If you are trying to debug something in a production system, it's very important to have as much information as possible when catching and logging exceptions. print_exception throws away a lot of important information (everything down the stack), and pkdexc was added to include that info.

pkdebug_test.test_pkdexc
fails in py3 with format_exception, because it only gives the calling context from the try, which is not what's wanted.

Traceback (most recent call last):
  File "/home/vagrant/src/radiasoft/pykern/tests/pkdebug_test.py", line 230, in tag1234
    force_error()
  File "/home/vagrant/src/radiasoft/pykern/tests/pkdebug_test.py", line 226, in force_error
    xyzzy
NameError: name 'xyzzy' is not defined

This doesn't include the calling routine (test_pkdexc) so the test fails.

Here's my proposed solution, which allows the test to pass:

        e = sys.exc_info()
        # py2 doesn't cascade exceptions
        stack = traceback.format_stack()[:-2]
        if hasattr(traceback, 'TracebackException'):
            stack += traceback.format_exception(*e)
        else:
            stack +=  traceback.format_tb(e[2])
        return ''.join(traceback.format_exception_only(e[0], e[1]) + stack)

[njsmith]

Right that's what I was saying here :-)

This does mean we can't as easily graft the current stack onto the exception's stack, like pkdexc does now. But we could print the current stack with a little header like Exception encountered at:\n + current stack + format_exception output.

I think your proposed solution gives confusing output if the exception has __context__ / __cause__ attributes -- basically it grafts the current stack onto the wrong traceback.

Here's some code:

def raise_KeyError():
    dict()['foo']

def exposed_api():
    try:
        raise_KeyError()
    except KeyError:
        # Replace the exception with something else
        raise RuntimeError('got a KeyError')

def outer_func():
    try:
        exposed_api()
    except:
        print(''.join(traceback.format_exception(*sys.exc_info())))

outer_func()

Here's what it prints:

Traceback (most recent call last):
  File "<stdin>", line 3, in exposed_api
  File "<stdin>", line 2, in raise_KeyError
KeyError: 'foo'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):                                          <--- HERE
  File "<stdin>", line 3, in outer_func
  File "<stdin>", line 6, in exposed_api
RuntimeError: got a KeyError

Notice that it's kind of "inside out" – inside each section you read from bottom to top, but you read the sections themselves from top to bottom. The place marked <--- HERE is where pkdexc wants to graft in the current stack. Actually grafting it there seems tricky though. So my suggestion would be to stick a new section on – actually maybe it should be at the end? So something like:

Traceback (most recent call last):
  File "<stdin>", line 3, in exposed_api
  File "<stdin>", line 2, in raise_KeyError
KeyError: 'foo'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<stdin>", line 3, in outer_func
  File "<stdin>", line 6, in exposed_api
RuntimeError: got a KeyError

Exception was caught at:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "<stdin>", line 5, in <outer_func>