connexion
connexion copied to clipboard
spec-first
Stack trace not available to logger in v3 error handler function
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:
- activate the v2 venv:
source venv-v2/bin/activate - create a symlink:
ln -s hello_v2.py hello.py(the spec files point to modulehello) - run the app:
python3 hello.py - 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:
- activate the v3 venv:
source venv-v3/bin/activate - create a symlink:
ln -s hello_v3.py hello.py(again this avoids changing the operation ID in the spec files) - run the app:
python3 hello.py - 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
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.
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.
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:
- What can I do in my exception handler, and what can't I do, now that it's mysteriously
async? - Would you look favorably on a PR to update this page: https://connexion.readthedocs.io/en/latest/exceptions.html
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.
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 https://github.com/spec-first/connexion/pull/2021
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:
https://github.com/spec-first/connexion/blob/1844a2fb3f1d09a37edfeab7a7200d52e97abbd9/connexion/middleware/exceptions.py#L36-L39
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.
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.
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.
Happy new year @RobbeSneyders I think I addressed all your comments in this revised PR, would you please review?
Finally getting back to updating this issue. @RobbeSneyders pointed out that I can supply argument exc_info in the logger.exception call, and that neatly solves the problem, a stack trace is then shown just fine.