Stack trace not available to logger in v3 error handler function #2019
Description
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