Bug: exceptions are logged twice #3228

jderrien · 2024-03-19T11:49:19Z

Description

Exceptions are logged twice

URL to code causing the issue

No response

MCVE

from litestar import get, Litestar, Request
from litestar.logging import LoggingConfig


@get("/exc")
async def exception_route(request: Request) -> str:
    request.logger.info("Reaching exception route endpoint")
    raise RuntimeError("Something went wrong")
    return "never reached"


app = Litestar(route_handlers=[exception_route],
               logging_config=LoggingConfig(log_exceptions="always"))

Steps to reproduce

No response

Screenshots

No response

Logs

$ .venv/bin/litestar run
Using Litestar app from app:app
Starting server process ─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
┌──────────────────────────────┬──────────────────────┐
│ Litestar version             │ 2.7.0                │
│ Debug mode                   │ Disabled             │
│ Python Debugger on exception │ Disabled             │
│ CORS                         │ Disabled             │
│ CSRF                         │ Disabled             │
│ OpenAPI                      │ Enabled path=/schema │
│ Compression                  │ Disabled             │
└──────────────────────────────┴──────────────────────┘
INFO:     Started server process [94846]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO - 2024-03-19 12:48:04,135 - root - app - Reaching exception route endpoint
INFO:     127.0.0.1:58369 - "GET /exc HTTP/1.1" 500 Internal Server Error
ERROR - 2024-03-19 12:48:04,136 - litestar - config - exception raised on http connection to route /exc

Traceback (most recent call last):
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 218, in __call__
    await self.app(scope, receive, send)
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 82, in handle
    response = await self._get_response_for_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 134, in _get_response_for_request
    return await self._call_handler_function(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 154, in _call_handler_function
    response_data, cleanup_group = await self._get_response_data(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 207, in _get_response_data
    data = await route_handler.fn(**parsed_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/app.py", line 8, in exception_route
    raise RuntimeError("Something went wrong")
RuntimeError: Something went wrong
Traceback (most recent call last):
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 218, in __call__
    await self.app(scope, receive, send)
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 82, in handle
    response = await self._get_response_for_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 134, in _get_response_for_request
    return await self._call_handler_function(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 154, in _call_handler_function
    response_data, cleanup_group = await self._get_response_data(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 207, in _get_response_data
    data = await route_handler.fn(**parsed_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/app.py", line 8, in exception_route
    raise RuntimeError("Something went wrong")
RuntimeError: Something went wrong

Litestar Version

litestar==2.7.0

Platform

Linux
Mac
Windows
Other (Please specify in the description above)

Note

While we are open for sponsoring on GitHub Sponsors and
OpenCollective, we also utilize Polar.sh to engage in pledge-based sponsorship.

Check out all issues funded or available for funding on our Polar.sh dashboard

If you would like to see an issue prioritized, make a pledge towards it!
We receive the pledge once the issue is completed & verified
This, along with engagement in the community, helps us know which features are a priority to our users.

The text was updated successfully, but these errors were encountered:

jderrien · 2024-03-19T11:55:42Z

I can fix that for standard/picologging logging.

But I'm not sure what's expected for structlog, the traceback is printed is 2 different formats:

2024-03-19T11:53:25.333709Z [info     ] HTTP Request                   body=None content_type=('', {}) cookies={} headers={'host': '127.0.0.1:8000', 'user-agent': 'curl/8.1.2', 'accept': '*/*'} method=GET path=/exc path_params={} query={}
2024-03-19T11:53:25.334041Z [info     ] Reaching exception route endpoint
2024-03-19T11:53:25.335059Z [error    ] Uncaught Exception             connection_type=http path=/exc traceback=  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 218, in __call__
    await self.app(scope, receive, send)
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 82, in handle
    response = await self._get_response_for_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 134, in _get_response_for_request
    return await self._call_handler_function(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 154, in _call_handler_function
    response_data, cleanup_group = await self._get_response_data(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 207, in _get_response_data
    data = await route_handler.fn(**parsed_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar-minimal/app.py", line 8, in exception_route
    raise RuntimeError("Something went wrong")
RuntimeError: Something went wrong

╭───────────────────── Traceback (most recent call last) ──────────────────────╮
│ /Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages │
│ /litestar/middleware/exceptions/middleware.py:218 in __call__                │
│                                                                              │
│   215 │   │   │   None                                                       │
│   216 │   │   """                                                            │
│   217 │   │   try:                                                           │
│ ❱ 218 │   │   │   await self.app(scope, receive, send)                       │
│   219 │   │   except Exception as e:  # noqa: BLE001                         │
│   220 │   │   │   litestar_app = scope["app"]                                │
│   221                                                                        │
│                                                                              │
│ /Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages │
│ /litestar/routes/http.py:82 in handle                                        │
│                                                                              │
│    79 │   │   if route_handler.resolve_guards():                             │
│    80 │   │   │   await route_handler.authorize_connection(connection=reques │
│    81 │   │                                                                  │
│ ❱  82 │   │   response = await self._get_response_for_request(               │
│    83 │   │   │   scope=scope, request=request, route_handler=route_handler, │
│    84 │   │   )                                                              │
│    85                                                                        │
│                                                                              │
│                           ... 2 frames hidden ...                            │
│                                                                              │
│ /Users/jderrien/projects/litestar-minimal/.venv/lib/python3.11/site-packages │
│ /litestar/routes/http.py:207 in _get_response_data                           │
│                                                                              │
│   204 │   │   elif route_handler.has_sync_callable:                          │
│   205 │   │   │   data = route_handler.fn(**parsed_kwargs)                   │
│   206 │   │   else:                                                          │
│ ❱ 207 │   │   │   data = await route_handler.fn(**parsed_kwargs)             │
│   208 │   │                                                                  │
│   209 │   │   return data, cleanup_group                                     │
│   210                                                                        │
│                                                                              │
│ /Users/jderrien/projects/litestar-minimal/app.py:8 in exception_route        │
│                                                                              │
│    5 @get("/exc")                                                            │
│    6 async def exception_route(request: Request) -> str:                     │
│    7 │   request.logger.info("Reaching exception route endpoint")            │
│ ❱  8 │   raise RuntimeError("Something went wrong")                          │
│    9 │   return "never reached"                                              │
│   10                                                                         │
│   11 """                                                                     │
╰──────────────────────────────────────────────────────────────────────────────╯
RuntimeError: Something went wrong

INFO:     127.0.0.1:58410 - "GET /exc HTTP/1.1" 500 Internal Server Error
2024-03-19T11:53:25.380988Z [info     ] HTTP Response                  body={"status_code":500,"detail":"Internal Server Error"} cookies={} headers={'content-type': 'text/plain; charset=utf-8', 'content-length': '52'} status_code=500

github-actions · 2024-06-02T16:36:06Z

A fix for this issue has been released in v2.9.0

jderrien added the Bug 🐛 This is something that is not working as expected label Mar 19, 2024

jderrien mentioned this issue May 17, 2024

fix(logging): do not log exceptions twice, deprecate traceback_line_limit and fix pretty_print_tty #3507

Merged

jderrien changed the title ~~Bug: exception are logged twice~~ Bug: exceptions are logged twice May 27, 2024

provinzkraut closed this as completed in #3507 May 30, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug: exceptions are logged twice #3228

Bug: exceptions are logged twice #3228

jderrien commented Mar 19, 2024 •

edited

jderrien commented Mar 19, 2024 •

edited

github-actions bot commented Jun 2, 2024

Bug: exceptions are logged twice #3228

Bug: exceptions are logged twice #3228

Comments

jderrien commented Mar 19, 2024 • edited

Description

URL to code causing the issue

MCVE

Steps to reproduce

Screenshots

Logs

Litestar Version

Platform

jderrien commented Mar 19, 2024 • edited

github-actions bot commented Jun 2, 2024

jderrien commented Mar 19, 2024 •

edited

jderrien commented Mar 19, 2024 •

edited