openwallet-foundation / acapy

ACA-Py is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://aca-py.org
Apache License 2.0
419 stars 512 forks source link

Improve exception handling to reduce unnecessary stack traces #3322

Closed ff137 closed 2 weeks ago

ff137 commented 3 weeks ago

The ready_middleware function in admin/server.py has the following implementation:

@web.middleware
async def ready_middleware(request: web.BaseRequest, handler: Coroutine):
    """Only continue if application is ready to take work."""

    if str(request.rel_url).rstrip("/") in (
        "/status/live",
        "/status/ready",
    ) or request.app._state.get("ready"):
        try:
            return await handler(request)
        except (LedgerConfigError, LedgerTransactionError) as e:
            # fatal, signal server shutdown
            LOGGER.error("Shutdown with %s", str(e))
            request.app._state["ready"] = False
            request.app._state["alive"] = False
            raise
        except web.HTTPFound as e:
            # redirect, typically / -> /api/doc
            LOGGER.info("Handler redirect to: %s", e.location)
            raise
        except asyncio.CancelledError:
            # redirection spawns new task and cancels old
            LOGGER.debug("Task cancelled")
            raise
        except Exception as e:
            # some other error?
            LOGGER.error("Handler error with exception: %s", str(e))
            import traceback

            print("\n=================")
            traceback.print_exc()
            raise

    raise web.HTTPServiceUnavailable(reason="Shutdown in progress")

This needs a makeover. In particular, the way that base exceptions are handled with an error log and stack trace being printed out.

In many cases, the stack trace is wholly uninformative, and just clutters the logs. For example: invalid token, record not found, or any other bad client requests, will print a redundant stack trace as follows:

Handler error with exception: Token not valid.
=================
Traceback (most recent call last):
  File "/home/aries/.local/lib/python3.12/site-packages/aries_cloudagent/admin/server.py", line 310, in setup_context
    profile = await self.multitenant_manager.get_profile_for_token(
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/aries_cloudagent/multitenant/base.py", line 381, in get_profile_for_token
    raise MultitenantManagerError("Token not valid")
aries_cloudagent.multitenant.base.MultitenantManagerError: Token not valid
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/home/aries/.local/lib/python3.12/site-packages/aries_cloudagent/admin/server.py", line 141, in ready_middleware
    return await handler(request)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/aries_cloudagent/admin/server.py", line 212, in debug_middleware
    return await handler(request)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/aries_cloudagent/admin/server.py", line 326, in setup_context
    raise web.HTTPUnauthorized(reason=err.roll_up)
aiohttp.web_exceptions.HTTPUnauthorized: Token not valid.

In the coming days I'll post a PR to handle exceptions more gracefully, and help reduce the cases where stack traces are printed.

ff137 commented 3 weeks ago

Passing a bad tenant token (cannot be decoded by jwt library) results in:

2024-10-31 12:07:33,884 acapy_agent.admin.server ERROR Handler error with exception: Unauthorized
=================
Traceback (most recent call last):
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 310, in setup_context
    profile = await self.multitenant_manager.get_profile_for_token(
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/multitenant/base.py", line 365, in get_profile_for_token
    token_body = jwt.decode(token, jwt_secret, algorithms=["HS256"], leeway=1)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/jwt/api_jwt.py", line 211, in decode
    decoded = self.decode_complete(
              ^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/jwt/api_jwt.py", line 152, in decode_complete
    decoded = api_jws.decode_complete(
              ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/jwt/api_jws.py", line 210, in decode_complete
    self._verify_signature(signing_input, header, signature, key, algorithms)
  File "/home/aries/.local/lib/python3.12/site-packages/jwt/api_jws.py", line 317, in _verify_signature
    raise InvalidSignatureError("Signature verification failed")
jwt.exceptions.InvalidSignatureError: Signature verification failed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 141, in ready_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 212, in debug_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 328, in setup_context
    raise web.HTTPUnauthorized()
aiohttp.web_exceptions.HTTPUnauthorized: Unauthorized

Passing an incorrectly formatted token (without "Bearer" at the start) results in:

=================
2024-10-31 12:12:28,694 acapy_agent.admin.server ERROR Handler error with exception: Invalid Authorization header structure
Traceback (most recent call last):
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 141, in ready_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 212, in debug_middleware
    return await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/aries/.local/lib/python3.12/site-packages/acapy_agent/admin/server.py", line 306, in setup_context
    raise web.HTTPUnauthorized(
aiohttp.web_exceptions.HTTPUnauthorized: Invalid Authorization header structure