CODEWITHSUNDEEP
pythonloggingformattornado
Quan Vuong
Quan Vuong

Reputation: 1999

Correct logging for exception in coroutine Python3 + Tornado4.3 + native logging module

In Tornado, an Exception is encapsulated within a Future and the caller to an async function must yield the Future to unpack the Exception. How do I get the log message to correctly print out the function name and line where the exception happens if I have a long calling chain of async functions ?

For example, in the code below:

FORMAT = '%(asctime)s - %(levelname)s - %(filename)s : %(lineno)s'\
         ' - %(funcName)20s() - %(message)s\n'

logging.basicConfig(format=FORMAT)

...

@gen.coroutine
def layer_2():
    return(yield async_func())

@gen.coroutine 
def layer_1():
    return(yield layer_2())

@gen.coroutine
def main():
    try:
        yield layer_1()
    except Exception as e:
        logging.warning('Error: {}'.format(str(e))

If there is an Exception raised in async_func(), the log message lineno and funcName are those of main(), not of async_func().

Is there any solution short of try and catch every yield statement ? Thanks!

Edit 1: I realized the answer to my question might have nothing to do with Tornado, but I'm just including it here because it's my case.

Upvotes: 0

Views: 723

Answers (1)

A. Jesse Jiryu Davis
A. Jesse Jiryu Davis

Reputation: 24007

I see you're using Python 3, and in Python 3, exceptions from Futures have a traceback available automatically. Use logging.exception to print it:

@gen.coroutine
def main():
    try:
        yield layer_1()
    except Exception as e:
        logging.exception(e)

There's nothing mysterious going on in logging. You can print the traceback yourself:

@gen.coroutine
def main():
    try:
        yield layer_1()
    except Exception as e:
        import traceback
        traceback.print_exc()

Compared to a traceback from a regular function call stack, this traceback has some extra stuff in it: calls to gen.Runner.run, part of Tornado's coroutine implementation. But it serves its purpose: you can see that main is at the top of the stack and async_func is at the bottom.

This works in Python 3 because every Exception has a Traceback attached to it, and Tornado correctly attaches a coroutine's traceback to the exception as it unwinds the stack during exception handling. For some history, see the docs on Future.

And finally, if you replace gen.coroutine with async def you'll get nice clean tracebacks implemented by the Python 3.5 interpreter itself.

Upvotes: 3

Related Questions