3,034 reads

Reducing Debugging Woes with Python Async Decorator

by GIWYNIOctober 8th, 2019

Too Long; Didn't Read

Python Async Decorator is a decorator for the Python programming language. The decorator logs exceptions as they occur and hence the problem shows up in your logs immediately. The problem is that the calling process is waiting on an 'await' and hence ends up not processing any exceptions, resulting in a 'Whats happening? When the what happened?' situation depicted above. The code below is a simple program containing two. processes, one generating data for the other executing indefinitely (or forever -- limited to 30 seconds in the demo below)

featured image - Reducing Debugging Woes with Python Async Decorator

You like asynchronous programming, and appreciate the elegance of await, tasks and similar in making asynchronous programming more intuitive and understandable and while all is good, you will likely find that async debugging is quite tough!

Exceptions in the async processes often won't show up in the console or logs until the program itself is terminated. You end up watching your program just wait when it should have shown an exception and spurred you into debugging!

The stages of asynchronous creativity are as below:

The underlying reason for the delayed logging of exceptions is that they bubble up to the calling process, which itself is an async process and will process the exceptions only when it is ready to run in the async loop. Often the calling process is waiting on an 'await' and hence ends up not processing any exceptions, resulting in 'Whats happening? When the what happened?' situation depicted above!

Before delving into the issue, here is a solution (you do not have to read any further if you already know the problem and use the decorator below as befitting your code):

import asyncio
import pprint, traceback, functools
import datetime

def exceptionCatcherForAsyncDecorator():
    def deco(func):
        @functools.wraps(func)
        async def wrapped(*args):
            print('wrap function invoked')
            try:
                return await func(*args)
            except Exception as E:
                print(f'Exception occured at: {datetime.datetime.now()}\n {pprint.pformat(traceback.format_exc())}')
                raise #re-raise exception to allow process in calling function
        return wrapped
    return deco

This is a decorator for the async functions that logs exceptions as they occur and hence the problem shows up in your logs immediately as they occur. In this decorator the print function is used to log the exceptions.

Problem Description

I got into this issue when coding a simple async program containing two async process, one generating data for the other and each executing indefinitely (or forever -- limited to 30 seconds in the demo below).

Here is the abstracted code simulating the two async processes also showing the decorator at the top:

import asyncio
import pprint, traceback, functools
import datetime

def exceptionCatcherForAsyncDecorator():
    def deco(func):
        @functools.wraps(func)
        async def wrapped(*args):
            print('wrap function invoked')
            try:
                return await func(*args)
            except Exception as E:
                print(f'Exception occured at: {datetime.datetime.now()}\n {pprint.pformat(traceback.format_exc())}')
                raise #re-raise exception to allow process in calling function
        return wrapped
    return deco

########## Main program starts here ##############
import random
#@exceptionCatcherForAsyncDecorator() -- decorator commented out for demo
async def doProcessing(m,n):
    await asyncio.sleep(1)
    print(f'{m};{n};{m/n}')
    return m/n

async def callProcessing():
    while True:
        myNumerator=random.randint(1,100)
        myDenominator=random.randint(0,2)
        result=await doProcessing(myNumerator,myDenominator)
        print(f'result = {result}')


async def main():
    # spawn task to create events
    evtCreator_task = asyncio.create_task(callProcessing())
    # Sleep for and terminate.
    sleepTime=30
    print(f'Time now: {datetime.datetime.now()} - Sleeping for {sleepTime} seconds..')
    await asyncio.sleep(sleepTime)
    print (f'Time now: {datetime.datetime.now()}')
    print('..Terminated!')

asyncio.run(main())

The two processes in the main program are:

a. doProcessing (simulates complex processing). Here it 'occasionally' generates an exception 'division by 0'.

b. callProcessing (supplies input to doProcessing)

The third process main() starts the program. The main() terminates after 30 seconds and causes the doProcessing and callProcessing to be cancelled.

Running this code without the decorator (as shown above, the decorator is commented out) results in the exception being visible only after 30 seconds as shown below:

$ python asyncDecorator.py 
Time now: 2019-09-30 11:24:13.785183 - Sleeping for 30 seconds..
Time now: 2019-09-30 11:24:43.799021  <== 30 seconds have elapsed..
..Terminated!
Task exception was never retrieved
future: <Task finished coro=<callProcessing() done, defined at asyncDecorator.py:26> exception=ZeroDivisionError('division by zero')>
Traceback (most recent call last):
  File "asyncDecorator.py", line 30, in callProcessing
    result=await doProcessing(myNumerator,myDenominator)
  File "asyncDecorator.py", line 23, in doProcessing
    print(f'{m};{n};{m/n}')
ZeroDivisionError: division by zero

Running the same code with the decorator active (i.e. decorator uncommented) results in the exception being logged immediately as it occurred:

$ python asyncDecorator.py 
Time now: 2019-09-30 11:32:29.895473 - Sleeping for 30 seconds..
wrap function invoked
Exception occured at: 2019-09-30 11:32:30.896903  <== exception logged as it occurs !
 ('Traceback (most recent call last):\n'
 '  File "asyncDecorator.py", line 11, in wrapped\n'
 '    return await func(*args)\n'
 '  File "asyncDecorator.py", line 23, in doProcessing\n'
 "    print(f'{m};{n};{m/n}')\n"
 'ZeroDivisionError: division by zero\n')
Time now: 2019-09-30 11:32:59.913337 <== 30 seconds elapsed..
..Terminated!
Task exception was never retrieved <== exception logged again due to re-raise by decorator
future: <Task finished coro=<callProcessing() done, defined at asyncDecorator.py:26> exception=ZeroDivisionError('division by zero')>
Traceback (most recent call last):
  File "asyncDecorator.py", line 30, in callProcessing
    result=await doProcessing(myNumerator,myDenominator)
  File "asyncDecorator.py", line 11, in wrapped
    return await func(*args)
  File "asyncDecorator.py", line 23, in doProcessing
    print(f'{m};{n};{m/n}')
ZeroDivisionError: division by zero

So if you are perplexed as to what is happening to your async program, this decorator may help.