Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stack trace not available to logger in v3 error handler function #2019

Open
chrisinmtown opened this issue Dec 13, 2024 · 9 comments · May be fixed by #2021
Open

Stack trace not available to logger in v3 error handler function #2019

chrisinmtown opened this issue Dec 13, 2024 · 9 comments · May be fixed by #2021

Comments

@chrisinmtown
Copy link
Contributor

chrisinmtown commented Dec 13, 2024

Description

Please help me convince the V3 error-handler function to log a complete stack trace when an exception is raised. As far as I can tell, the stack trace is not available, and that change is a regression from V2. A stack trace is critical for discovering what really failed. For example, if some function raises KeyError('1') the message is just 1 and that's not really helpful if operations brings that back from a production error!

Expected behaviour

In a function hooked via the add_error_handler function, calling logger.exception will log a full stack trace.

Actual behaviour

In a function hooked via the add_error_handler function, calling logger.exception yields only a string version of the exception, same as calling logger.error; no stack trace is logged.

Steps to reproduce

Start with the directory https://github.com/spec-first/connexion/tree/main/examples/helloworld and add the python files with the content below.

Here's hello_v2.py for Connexion V2 which works as I expect, calling logger.exception prints a stack trace on exception:

from connexion import App
import logging


def handle_exception(ex):
    logger.exception("Request caused exc: %s", ex)
    return {"detail": str(ex)}, 500


def fall_on_face() -> None:
    logger.warning("Prepare to crash")
    raise ValueError("I would prefer not to")


def post_greeting(name: str) -> str:
    logger.info("name is %s", name)
    fall_on_face()


logger = logging.getLogger(__name__)
logging.basicConfig(level=logging.INFO)
app = App(__name__, specification_dir="spec/")
app.add_error_handler(Exception, handle_exception)
app.add_api("openapi.yaml", arguments={"title": "Hello World Example"})
app.add_api("swagger.yaml", arguments={"title": "Hello World Example"})


if __name__ == "__main__":
    app.app.run(port=8080)

Here's hello_v3.py for Connexion V3 which somehow does not preserve the stack trace (?)

from connexion import FlaskApp
from connexion.lifecycle import ConnexionRequest, ConnexionResponse
from connexion.problem import problem
import logging
from pathlib import Path


def handle_exception(
        request: ConnexionRequest,
        ex: Exception) -> ConnexionResponse:
    logger.exception("Request caused exc: %s", ex)
    return problem(title='Exception', status=500, detail=str(ex))


def fall_on_face() -> None:
    logger.warning("Prepare to crash")
    raise ValueError("I would prefer not to")


def post_greeting(name: str) -> str:
    logger.info("name is %s", name)
    fall_on_face()


logger = logging.getLogger(__name__)
logging.basicConfig(level=logging.INFO)
app = FlaskApp(__name__, specification_dir="spec/")
app.add_error_handler(Exception, handle_exception)
app.add_api("openapi.yaml", arguments={"title": "Hello World Example"})
app.add_api("swagger.yaml", arguments={"title": "Hello World Example"})


if __name__ == "__main__":
    app.run(f"{Path(__file__).stem}:app", port=8080)

Next you'll have to create two virtual environments:

python3 -m venv venv-v2
source venv-v2/bin/activate
pip install 'connexion[flask,swagger-ui]<3'             
deactivate

python3 -m venv venv-v3
source venv-v3/bin/activate
pip install 'connexion[flask,swagger-ui,uvicorn]>=3.1.0'
deactivate

Now you can run the v2 version, which yields a stack trace:

  1. activate the v2 venv: source venv-v2/bin/activate
  2. create a symlink: ln -s hello_v2.py hello.py (the spec files point to module hello)
  3. run the app: python3 hello.py
  4. view the swagger UI, click try it out.

Here's the log output I get from v2:

INFO:hello:name is dave
WARNING:hello:Prepare to crash
ERROR:__main__:Request caused exc: I would prefer not to
Traceback (most recent call last):
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/flask/app.py", line 1823, in full_dispatch_request
    rv = self.dispatch_request()
         ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/flask/app.py", line 1799, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/decorator.py", line 68, in wrapper
    response = function(request)
               ^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/uri_parsing.py", line 149, in wrapper
    response = function(request)
               ^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/validation.py", line 196, in wrapper
    response = function(request)
               ^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/validation.py", line 399, in wrapper
    return function(request)
           ^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/produces.py", line 41, in wrapper
    response = function(request)
               ^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v2/lib/python3.12/site-packages/connexion/decorators/parameter.py", line 120, in wrapper
    return function(**kwargs)
           ^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/hello.py", line 20, in post_greeting
    fall_on_face()
  File "/Users/me/git/github/connexion_spec_first/examples/exception/hello.py", line 15, in fall_on_face
    raise ValueError("I would prefer not to")
ValueError: I would prefer not to
INFO:werkzeug:127.0.0.1 - - [13/Dec/2024 13:24:50] "POST /openapi/greeting/dave HTTP/1.1" 500 -

Finally you can run the v3 version:

  1. activate the v3 venv: source venv-v3/bin/activate
  2. create a symlink: ln -s hello_v3.py hello.py (again this avoids changing the operation ID in the spec files)
  3. run the app: python3 hello.py
  4. view the swagger UI, click try it out.

Here's the log output I get from v3:

INFO:hello:name is dave
WARNING:hello:Prepare to crash
ERROR:hello:Request caused exc: I would prefer not to
NoneType: None
INFO:     127.0.0.1:58799 - "POST /openapi/greeting/dave HTTP/1.1" 500 Internal Server Error

I am pretty sure that the line with NoneType: None shown after my ERROR log output and before the access-log entry is from the logger._log function when it tries to discover & print a stack trace.

For what it's worth, if no error handler function is hooked, I get a full stack trace on the console! I'll show it here just for completeness.

INFO:hello:name is dave
WARNING:hello:Prepare to crash
ERROR:connexion.middleware.exceptions:ValueError('I would prefer not to')
Traceback (most recent call last):
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/_exception_handler.py", line 42, in wrapped_app
    await app(scope, receive, sender)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/swagger_ui.py", line 222, in __call__
    await self.router(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 715, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 735, in app
    await route.handle(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 460, in handle
    await self.app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 715, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 765, in app
    await self.default(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/swagger_ui.py", line 235, in default_fn
    await self.app(original_scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/routing.py", line 154, in __call__
    await self.router(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 715, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 735, in app
    await route.handle(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/me/routing.py", line 460, in handle
    await self.app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 715, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 735, in app
    await route.handle(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/starlette/routing.py", line 288, in handle
    await self.app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/routing.py", line 48, in __call__
    await self.next_app(original_scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/abstract.py", line 264, in __call__
    return await operation(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/security.py", line 106, in __call__
    await self.next_app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/abstract.py", line 264, in __call__
    return await operation(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/request_validation.py", line 142, in __call__
    await self.next_app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/abstract.py", line 264, in __call__
    return await operation(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/lifespan.py", line 26, in __call__
    await self.next_app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/abstract.py", line 264, in __call__
    return await operation(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/middleware/context.py", line 25, in __call__
    await self.next_app(scope, receive, send)
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/apps/flask.py", line 151, in __call__
    return await self.asgi_app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 165, in __call__
    return await responder(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 200, in __call__
    await self.loop.run_in_executor(
  File "/opt/homebrew/Cellar/[email protected]/3.12.7_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 256, in wsgi
    iterable = self.app(environ, start_response)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/flask/app.py", line 1514, in wsgi_app
    response = self.handle_exception(e)
               ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/flask/app.py", line 1511, in wsgi_app
    response = self.full_dispatch_request()
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/flask/app.py", line 919, in full_dispatch_request
    rv = self.handle_user_exception(e)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/flask/app.py", line 917, in full_dispatch_request
    rv = self.dispatch_request()
         ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/flask/app.py", line 902, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)  # type: ignore[no-any-return]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/apps/flask.py", line 68, in __call__
    return self.fn(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/decorators/main.py", line 134, in wrapper
    return decorated_function(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/decorators/response.py", line 171, in wrapper
    handler_response = function(*args, **kwargs)
                       ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/decorators/parameter.py", line 87, in wrapper
    return function(**kwargs)
           ^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/venv-v3/lib/python3.12/site-packages/connexion/decorators/main.py", line 123, in wrapper
    return function(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/me/git/github/connexion_spec_first/examples/exception/hello.py", line 22, in post_greeting
    fall_on_face()
  File "/Users/me/git/github/connexion_spec_first/examples/exception/hello.py", line 17, in fall_on_face
    raise ValueError("I would prefer not to")
ValueError: I would prefer not to
INFO:     127.0.0.1:60200 - "POST /openapi/greeting/dave HTTP/1.1" 500 Internal Server Error

Additional info:

Python 3.12
Connexion 3.1.0

@chrisinmtown
Copy link
Contributor Author

chrisinmtown commented Dec 15, 2024

By using the debugger I was able to figure out that the Python logging function _log calls system.exc_info() in this code block, about line 1657 in logging/__init__.py.:

        if exc_info:
            if isinstance(exc_info, BaseException):
                exc_info = (type(exc_info), exc_info, exc_info.__traceback__)
            elif not isinstance(exc_info, tuple):
                exc_info = sys.exc_info()

When connexion v2 handles an exception, that function returns something useful:

> /usr/local/Cellar/[email protected]/3.13.0_1/Frameworks/Python.framework/Versions/3.13/lib/python3.13/logging/__init__.py(1661)_log()
-> exc_info = sys.exc_info()
(Pdb) sys.exc_info()
(<class 'ValueError'>, ValueError('I would prefer not to'), <traceback object at 0x10ebdb540>)

But under connexion v3, that function returns None:

(Pdb) sys.exc_info()
(None, None, None)

Restating the obvious, the doc on sys.exc_info() says it must be called from within an except block. I am still trying to find where connexion catches the exception and calls my handler. I sort of suspect that my little exception handler is being run in a sync-to-async conversion block, because this is the tiny stack trace that pdb shows me from inside the handler, sure doesn't look like the handler is being called from within an except block to me:

(Pdb) where
/usr/local/Cellar/[email protected]/3.13.0_1/Frameworks/Python.framework/Versions/3.13/lib/python3.13/threading.py(1012)_bootstrap()
-> self._bootstrap_inner()
/usr/local/Cellar/[email protected]/3.13.0_1/Frameworks/Python.framework/Versions/3.13/lib/python3.13/threading.py(1041)_bootstrap_inner()
-> self.run()
  /Users/me/git/github/chrisinmtown-forks/connexion/examples/helloworld/venv-v3/lib/python3.13/site-packages/anyio/_backends/_asyncio.py(1005)run()
-> result = context.run(func, *args)
> /Users/me/git/github/chrisinmtown-forks/connexion/examples/helloworld/hello_v3.py(11)handle_exception()
-> breakpoint()

Please comment, how can connexion pass more context to my little exception handler? For example, I think in connexion.middleware.exceptions.py the function connexion_wrapper is running my handler in a thread pool. I suppose it could call sys.exc_info and pass the result in to my handler function? I realize that's crude & ugly tho.

@chrisinmtown
Copy link
Contributor Author

chrisinmtown commented Dec 15, 2024

Finally spotted this in the doc:

Error handlers can be async coroutines as well.

So if I define my exception handler as async, and the Connexion function doesn't have to run my synchronous handler in a thread pool, will the sys.exc_info call work then? Not quite sure what all is required for my handler to be async tho.

@chrisinmtown
Copy link
Contributor Author

I'm sure it will surprise none of the maintainers lol that this works just fine, the logger shows a full stack trace:

async def my_handle_exception(
        request: ConnexionRequest,
        ex: Exception) -> ConnexionResponse:
    logger.exception("Request caused exc: %s", ex)
    return problem(title='Exception', status=500, detail=str(ex))

Happy to have a solution, it raises many more questions:

chrisinmtown added a commit to chrisinmtown/connexion that referenced this issue Dec 17, 2024
Document that a regular function has no access to the exception stack traceback

Fixes spec-first#2019
chrisinmtown added a commit to chrisinmtown/connexion that referenced this issue Dec 18, 2024
Document that a regular function has no access to the exception stack traceback
Extend the `add_error_handler` function's Pydoc similarly

Fixes spec-first#2019
@RobbeSneyders
Copy link
Member

Thanks for the report @chrisinmtown.

I would propose a different fix though. Seems like we're losing the stacktrace info since we're running the sync function in a threadpool, which is probably not needed for error handlers.

So I would just call the error handler directly instead.

@chrisinmtown
Copy link
Contributor Author

chrisinmtown commented Dec 22, 2024

Thanks for the reply @RobbeSneyders.

Maybe you are telling me that the error handler is called from an async context already, so it doesn't really need to be declared async and called via await? Just trying to understand.

I think the project will def need some doc to help people migrate to version 3.1.0 and beyond. Please let me know what you decide, I will adjust or drop PR #2021

@RobbeSneyders
Copy link
Member

The error handler is being called from an async context. If the error handler is async, it is called using await. If it is not async, it is executed in a threadpool:

if asyncio.iscoroutinefunction(handler):
response = await handler(request, exc) # type: ignore
else:
response = await run_in_threadpool(handler, request, exc)

This is done to prevent the handler from blocking the event loop. The downside is that it loses the stack trace information.

Now I'm wondering if we really need to call exception handlers in a threadpool, since I assume they usually won't do a lot of io. We could just call the handler directly, which would preserve the stack trace for sync error handlers.

@RobbeSneyders
Copy link
Member

Looking at Starlette and FastAPI, they seem to have the same issue.

It's probably safest to keep running the sync handlers in a threadpool, since people might be logging errors.

So I would indeed go for a docs update, but I would not blindly recommend async handlers, since this can have other complications if users are using blocking io. I would just add a warning of the stacktrace being unavailable in sync handlers.

chrisinmtown added a commit to chrisinmtown/connexion that referenced this issue Dec 23, 2024
Document that a sync function is run in a threadpool and has no access
to the exception stack traceback, but an async function does.
Extend the `add_error_handler` function's Pydoc similarly

Fixes spec-first#2019
chrisinmtown added a commit to chrisinmtown/connexion that referenced this issue Dec 23, 2024
Document that a sync function is run in a threadpool and has no access
to the exception stack traceback, but an async function does.
Extend the `add_error_handler` function's Pydoc similarly

Fixes spec-first#2019
@chrisinmtown
Copy link
Contributor Author

chrisinmtown commented Dec 23, 2024

I revised my PR, it no longer blindly recommends async handlers, just warns that the stack trace is only available in an async coroutine. Please review.

chrisinmtown added a commit to chrisinmtown/connexion that referenced this issue Dec 27, 2024
Document that a sync function is run in a threadpool and has no access
to the exception stack traceback, but an async function does.
Extend the `add_error_handler` function's Pydoc similarly

Fixes spec-first#2019
@chrisinmtown
Copy link
Contributor Author

Happy new year @RobbeSneyders I think I addressed all your comments in this revised PR, would you please review?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants