azure-functions-python-worker icon indicating copy to clipboard operation
azure-functions-python-worker copied to clipboard

Python: support logging ExceptionGroup sub-exceptions

Open io-canopy opened this issue 7 months ago • 3 comments

Description

Using the following code:

#!/usr/bin/env python

import asyncio
import azure.functions as func

app = func.FunctionApp()

@app.timer_trigger(schedule='0 */1 * * * *', arg_name='mytimer', run_on_startup=True)
async def test_task_group_trigger(mytimer):
	await test_task_group()

async def test_task_group():
	async def inner_task(i):
		await asyncio.sleep(0)
		i/0

	async with asyncio.TaskGroup() as tg:
		for i in range(4):
			tg.create_task(inner_task(i))

if __name__ == '__main__':
	asyncio.run(test_task_group())

When run in the terminal, ./function_app.py, I get:

  + Exception Group Traceback (most recent call last):
  |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 22, in <module>
  |     asyncio.run(test_task_group())
  |   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/runners.py", line 195, in run
  |     return runner.run(main)
  |            ^^^^^^^^^^^^^^^^
  |   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/runners.py", line 118, in run
  |     return self._loop.run_until_complete(task)
  |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  |   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/base_events.py", line 691, in run_until_complete
  |     return future.result()
  |            ^^^^^^^^^^^^^^^
  |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 17, in test_task_group
  |     async with asyncio.TaskGroup() as tg:
  |                ^^^^^^^^^^^^^^^^^^^
  |   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/taskgroups.py", line 71, in __aexit__
  |     return await self._aexit(et, exc)
  |            ^^^^^^^^^^^^^^^^^^^^^^^^^^
  |   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/taskgroups.py", line 164, in _aexit
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (4 sub-exceptions)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 15, in inner_task
    |     i/0
    |     ~^~
    | ZeroDivisionError: division by zero
    +---------------- 2 ----------------
    | Traceback (most recent call last):
    |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 15, in inner_task
    |     i/0
    |     ~^~
    | ZeroDivisionError: division by zero
    +---------------- 3 ----------------
    | Traceback (most recent call last):
    |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 15, in inner_task
    |     i/0
    |     ~^~
    | ZeroDivisionError: division by zero
    +---------------- 4 ----------------
    | Traceback (most recent call last):
    |   File "/home/user/code/work/canopy/guidepost/tg-test/./function_app.py", line 15, in inner_task
    |     i/0
    |     ~^~
    | ZeroDivisionError: division by zero
    +------------------------------------

Which is quite helpful. Unfortunately, in func host start --verbose, I get the following traceback instead:

[2025-05-05T22:41:00.001Z] Executing 'Functions.test_task_group_trigger' (Reason='Timer fired at 2025-05-05T15:41:00.0009036-07:00', Id=f3dbc3f3-9b36-479c-bec8-8f73a4031247)
[2025-05-05T22:41:00.012Z] Received FunctionInvocationRequest, request ID: 660324cb-db0f-4c07-a270-f6c6ed38ca78, function ID: 71e25862-8f0b-570b-91de-6ee32efde7c7, function name: test_task_group_trigger, invocation ID: f3dbc3f3-9b36-479c-bec8-8f73a4031247, function type: async, timestamp (UTC): 2025-05-05 22:41:00.004631
[2025-05-05T22:41:00.016Z] Executed 'Functions.test_task_group_trigger' (Failed, Id=f3dbc3f3-9b36-479c-bec8-8f73a4031247, Duration=13ms)
[2025-05-05T22:41:00.016Z] System.Private.CoreLib: Exception while executing function: Functions.test_task_group_trigger. System.Private.CoreLib: Result: Failure
[2025-05-05T22:41:00.016Z] Exception: ExceptionGroup: unhandled errors in a TaskGroup (4 sub-exceptions)
[2025-05-05T22:41:00.016Z] Stack:   File "/usr/lib/azure-functions-core-tools/workers/python/3.12/LINUX/X64/azure_functions_worker/dispatcher.py", line 659, in _handle__invocation_request
[2025-05-05T22:41:00.016Z]     await self._run_async_func(fi_context, fi.func, args)
[2025-05-05T22:41:00.017Z]   File "/usr/lib/azure-functions-core-tools/workers/python/3.12/LINUX/X64/azure_functions_worker/dispatcher.py", line 996, in _run_async_func
[2025-05-05T22:41:00.017Z]     return await ExtensionManager.get_async_invocation_wrapper(
[2025-05-05T22:41:00.017Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[2025-05-05T22:41:00.017Z]   File "/usr/lib/azure-functions-core-tools/workers/python/3.12/LINUX/X64/azure_functions_worker/extension.py", line 143, in get_async_invocation_wrapper
[2025-05-05T22:41:00.017Z]     result = await function(**args)
[2025-05-05T22:41:00.017Z]              ^^^^^^^^^^^^^^^^^^^^^^
[2025-05-05T22:41:00.017Z]   File "/home/user/code/work/canopy/guidepost/tg-test/function_app.py", line 13, in test_task_group_trigger
[2025-05-05T22:41:00.017Z]     await test_task_group()
[2025-05-05T22:41:00.017Z]   File "/home/user/code/work/canopy/guidepost/tg-test/function_app.py", line 20, in test_task_group
[2025-05-05T22:41:00.017Z]     async with asyncio.TaskGroup() as tg:
[2025-05-05T22:41:00.017Z]                ^^^^^^^^^^^^^^^^^^^
[2025-05-05T22:41:00.017Z]   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/taskgroups.py", line 71, in __aexit__
[2025-05-05T22:41:00.017Z]     return await self._aexit(et, exc)
[2025-05-05T22:41:00.017Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^^
[2025-05-05T22:41:00.017Z]   File "/home/user/.local/share/pyenv/versions/3.12.10/lib/python3.12/asyncio/taskgroups.py", line 164, in _aexit
[2025-05-05T22:41:00.017Z]     raise BaseExceptionGroup(
[2025-05-05T22:41:00.017Z] .

Which isn't all that helpful. It would be nice if func host could log the inner exceptions in an ExceptionGroup so that using asyncio/anyio is a little friendlier.

io-canopy avatar May 05 '25 22:05 io-canopy

Hi @io-canopy, thanks for raising this. With our current architecture, when an exception is raised, we catch it and propagate forward the exception name and exception content. The top level exception is BaseExceptionGroup in this case, and that is what we return.

Essentially, our structure looks like this:

try:
// invoke function
except:
// handle any exceptions that occur in the function

Translated to the script, it would look similarly to this:

if __name__ == '__main__':
    try:
        asyncio.run(test_task_group())
    except Exception as e:
        print(f"Caught an exception: {e}.")

If my understanding is correct (and I could be wrong here), if the ExceptionGroup (or BaseExceptionGroup) is caught, then the sub-exceptions will not be propagated. The script wrapped in a try-catch block outputs only this: Caught an exception: unhandled errors in a TaskGroup (4 sub-exceptions)

We can look into perhaps handling sync vs. async exceptions differently. While we cannot change the try-catch structure, we might be able to check for sub-exceptions and output those as well.

In the meantime, to unblock your scenario, you can catch and handle all the sub-exceptions in your function code like so:

@app.timer_trigger(schedule='0 */1 * * * *', arg_name='mytimer', run_on_startup=True)
async def test_task_group_trigger(mytimer):
    try:
        await test_task_group()
    except* Exception as eg:  # Catch all exceptions from the task group
        logging.info(f"Caught an exception group: {eg}. Type: {type(eg)}")
        for e in eg.exceptions:
            logging.info(f"  - {type(e).__name__}: {e}")

That will output something like this:

[2025-05-21T19:59:52.069Z] Received FunctionInvocationRequest, request ID: 52f560d8-596f-4337-9464-aba1b9af1ee2, function ID: 71e25862-8f0b-570b-91de-6ee32efde7c7, function name: test_task_group_trigger, invocation ID: d5c42343-488b-4015-9f11-4342fb39172a, function type: async, timestamp (UTC): 2025-05-21 19:59:52.068228
[2025-05-21T19:59:52.076Z] Caught an exception group: unhandled errors in a TaskGroup (4 sub-exceptions). Type: <class 'ExceptionGroup'>
[2025-05-21T19:59:52.079Z]   - ZeroDivisionError: division by zero
[2025-05-21T19:59:52.080Z]   - ZeroDivisionError: division by zero
[2025-05-21T19:59:52.082Z]   - ZeroDivisionError: division by zero
[2025-05-21T19:59:52.083Z]   - ZeroDivisionError: division by zero

hallvictoria avatar May 21 '25 20:05 hallvictoria

Thank you for the workaround.

We can look into perhaps handling sync vs. async exceptions differently.

Yes, I would appreciate that greatly. Would you mind please pointing out where in the code that is handled, so that I may try my hand at a PR? For versions prior to 3.11, y'all could use https://pypi.org/project/exceptiongroup/#formatting-exception-groups, which includes

  • traceback.format_exception()
  • traceback.format_exception_only()
  • traceback.print_exception()
  • traceback.print_exc()

io-canopy avatar May 28 '25 21:05 io-canopy

Sure thing. Majority of the formatting is done in the _serialize_exception and marshall_exception_trace methods -- specifically, we use traceback.extract_tb.

The execution flow looks like this: invocation request -> exception occurs ->exception message is formatted

When we're formatting the exception, we first get the exception name and message. Then, we format the stack trace.

hallvictoria avatar May 29 '25 15:05 hallvictoria