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

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

Merged
merged 2 commits into from
May 30, 2024

Conversation

jderrien
Copy link
Contributor

@jderrien jderrien commented May 17, 2024

Description

Currently we're logging the exceptions twice: the full one and a truncated one.
This PR tries to improve this, which implies small breaking changes.

Almost finished but still a WIP, I need some feedback please!

Outlines:

  • The wording of the log message, when logging an exception, has been updated.
  • For structlog, the traceback field in the log message (which contained a truncated stacktrace) has been removed. The exception field is still around and contains the full stacktrace.
  • The option traceback_line_limit has been deprecated. The value is now ignored, the full stacktrace will be logged.

Summary

⚠️ The former code has been introduced to solve #1294, unfortunately I haven't been able to reproduce the issue. It's not clear in which cases it happened, or if the PR (#1296) fixed the original issue (I don't think so because exception are logged twice in the end).
TODO Anyway, to solve the original issue (#1294), truncating the request's body would have been a better solution. I'd be happy to dig a little bit more here. Any idea about how to reproduce the issue? (I already tried to write a test with a file upload, but the request's body doesn't get printed)
⚠️ Type ExceptionLoggingHandler and signature of handle_exception_logging() get updated by this PR, seems better and more flexible this way.

Logging

✅ Behavior is still the same, just slightly changed how we count the lines to display (see the code and the test test_traceback_truncate_default_logging).
✅ Ability to set traceback_line_limit to None.
⚠️ Default value for traceback_line_limit is None, I don't think we should truncate stacktraces by default.
❓ → ✅ Maybe we could deprecate traceback_line_limit to keep things in sync with Structlog. And if it's really something wanted by users, they can bring it back easily via a custom exception_logging_handler.
ℹ️ Updated log messages to get something similar to structlog.

StructLog

✅ Fixed a bug with pretty_print_tty (as a separated commit).
✅ When pretty_print_tty=True, we don't log the stacktrace twice and the remaining one gets truncated automatically by structlog (see below).
✅ When pretty_print_tty=False, exception gets logged as json. Previously it was logged in 2 separate fields (exception contains the full stacktrace & traceback a truncated version). This PR removes traceback. It will reduce the log size. It's still possible to parse the JSON after, with some tools, to limit the lines displayed.
❓ → ✅ If it's fine on your side, can I mark traceback_line_limit as deprecated and document it?

Extras

⚠️ Note: A few tests use structlog.testing.capture_logs. When using it to capture the logging.exception() output, the traceback is not yet rendered. That's something to keep in mind.
❓ What about turning log_exceptions to always by default? (Hiding errors by default seems a bad choice according to my sysadmin background).

Structlog: before & after

With pretty_print_tty=False

Before, both traceback and exception were logged:

{
  "connection_type": "http",
  "path": "/test",
  "traceback": "  File \"/Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/middleware.py\", line 158, in __call__\n    await self.app(scope, receive, capture_response_started)\n  File \"/Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py\", line 99, in __call__\n    await asgi_app(scope, receive, send)\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 80, in handle\n    response = await self._get_response_for_request(\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 132, in _get_response_for_request\n    return await self._call_handler_function(\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 152, in _call_handler_function\n    response_data, cleanup_group = await self._get_response_data(\n                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 203, in _get_response_data\n    data = route_handler.fn(**parsed_kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_handler_middleware.py\", line 299, in handler\n    raise ValueError(\"Test debug exception\")\nValueError: Test debug exception\n",
  "event": "Uncaught Exception",
  "level": "error",
  "exception": "Traceback (most recent call last):\n  File \"/Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/middleware.py\", line 158, in __call__\n    await self.app(scope, receive, capture_response_started)\n  File \"/Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py\", line 99, in __call__\n    await asgi_app(scope, receive, send)\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 80, in handle\n    response = await self._get_response_for_request(\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 132, in _get_response_for_request\n    return await self._call_handler_function(\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 152, in _call_handler_function\n    response_data, cleanup_group = await self._get_response_data(\n                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 203, in _get_response_data\n    data = route_handler.fn(**parsed_kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_handler_middleware.py\", line 299, in handler\n    raise ValueError(\"Test debug exception\")\nValueError: Test debug exception",
  "timestamp": "2024-05-16T22:07:01.991184Z"
}

After, we only log exception and the global size is reduced:

{
  "connection_type": "http",
  "path": "/test",
  "event": "Uncaught exception",
  "level": "error",
  "exception": "Traceback (most recent call last):\n  File \"/Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/middleware.py\", line 156, in __call__\n    await self.app(scope, receive, capture_response_started)\n  File \"/Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py\", line 99, in __call__\n    await asgi_app(scope, receive, send)\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 80, in handle\n    response = await self._get_response_for_request(\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 132, in _get_response_for_request\n    return await self._call_handler_function(\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 152, in _call_handler_function\n    response_data, cleanup_group = await self._get_response_data(\n                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/litestar/routes/http.py\", line 203, in _get_response_data\n    data = route_handler.fn(**parsed_kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_handler_middleware.py\", line 310, in handler\n    raise ValueError(\"Test debug exception\")\nValueError: Test debug exception",
  "timestamp": "2024-05-16T22:15:12.091675Z"
}

With pretty_print_tty=True:

Before, the truncated traceback value doesn't really help.

2024-05-16T22:03:40.912722Z [error    ] Uncaught Exception             connection_type=http path=/test traceback=  File "/Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 158, in __call__
    await self.app(scope, receive, capture_response_started)
  File "/Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py", line 99, in __call__
    await asgi_app(scope, receive, send)
  File "/Users/jderrien/projects/litestar/litestar/routes/http.py", line 80, in handle
    response = await self._get_response_for_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar/litestar/routes/http.py", line 132, in _get_response_for_request
    return await self._call_handler_function(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar/litestar/routes/http.py", line 152, in _call_handler_function
    response_data, cleanup_group = await self._get_response_data(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar/litestar/routes/http.py", line 203, in _get_response_data
    data = route_handler.fn(**parsed_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_handler_middleware.py", line 299, in handler
    raise ValueError("Test debug exception")
ValueError: Test debug exception

╭───────────────────── Traceback (most recent call last) ──────────────────────╮
│ /Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/m │
│ iddleware.py:158 in __call__                                                 │
│                                                                              │
│   155 │   │   │   await send(event)                                          │
│   156 │   │                                                                  │
│   157 │   │   try:                                                           │
│ ❱ 158 │   │   │   await self.app(scope, receive, capture_response_started)   │
│   159 │   │   except Exception as e:                                         │
│   160 │   │   │   if scope_state.response_started:                           │
│   161 │   │   │   │   raise LitestarException("Exception caught after respon │
│                                                                              │
│ /Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py:99 in        │
│ __call__                                                                     │
│                                                                              │
│    96 │   │   else:                                                          │
│    97 │   │   │   ScopeState.from_scope(scope).exception_handlers = route_ha │
│    98 │   │   │   scope["route_handler"] = route_handler                     │
│ ❱  99 │   │   await asgi_app(scope, receive, send)                           │
│   100 │                                                                      │
│   101 │   @lru_cache(1024)  # noqa: B019                                     │
│   102 │   def handle_routing(self, path: str, method: Method | None) -> tupl │
│                                                                              │
│                           ... 3 frames hidden ...                            │
│                                                                              │
│ /Users/jderrien/projects/litestar/litestar/routes/http.py:203 in             │
│ _get_response_data                                                           │
│                                                                              │
│   200 │   │   │   │   │   else await route_handler.fn(**parsed_kwargs)       │
│   201 │   │   │   │   )                                                      │
│   202 │   │   elif route_handler.has_sync_callable:                          │
│ ❱ 203 │   │   │   data = route_handler.fn(**parsed_kwargs)                   │
│   204 │   │   else:                                                          │
│   205 │   │   │   data = await route_handler.fn(**parsed_kwargs)             │
│   206                                                                        │
│                                                                              │
│ /Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_ │
│ handler_middleware.py:299 in handler                                         │
│                                                                              │
│   296 def test_traceback_truncate_struct_logging() -> None:                  │
│   297 │   @get("/test")                                                      │
│   298 │   def handler() -> None:                                             │
│ ❱ 299 │   │   raise ValueError("Test debug exception")                       │
│   300 │                                                                      │
│   301 │   app = Litestar([handler], logging_config=StructLoggingConfig(log_e │
│   302                                                                        │
╰──────────────────────────────────────────────────────────────────────────────╯
ValueError: Test debug exception

After (more concise):

2024-05-16T22:17:36.360643Z [error    ] Uncaught exception             connection_type=http path=/test
╭───────────────────── Traceback (most recent call last) ──────────────────────╮
│ /Users/jderrien/projects/litestar/litestar/middleware/_internal/exceptions/m │
│ iddleware.py:156 in __call__                                                 │
│                                                                              │
│   153 │   │   │   await send(event)                                          │
│   154 │   │                                                                  │
│   155 │   │   try:                                                           │
│ ❱ 156 │   │   │   await self.app(scope, receive, capture_response_started)   │
│   157 │   │   except Exception as e:                                         │
│   158 │   │   │   if scope_state.response_started:                           │
│   159 │   │   │   │   raise LitestarException("Exception caught after respon │
│                                                                              │
│ /Users/jderrien/projects/litestar/litestar/_asgi/asgi_router.py:99 in        │
│ __call__                                                                     │
│                                                                              │
│    96 │   │   else:                                                          │
│    97 │   │   │   ScopeState.from_scope(scope).exception_handlers = route_ha │
│    98 │   │   │   scope["route_handler"] = route_handler                     │
│ ❱  99 │   │   await asgi_app(scope, receive, send)                           │
│   100 │                                                                      │
│   101 │   @lru_cache(1024)  # noqa: B019                                     │
│   102 │   def handle_routing(self, path: str, method: Method | None) -> tupl │
│                                                                              │
│                           ... 3 frames hidden ...                            │
│                                                                              │
│ /Users/jderrien/projects/litestar/litestar/routes/http.py:203 in             │
│ _get_response_data                                                           │
│                                                                              │
│   200 │   │   │   │   │   else await route_handler.fn(**parsed_kwargs)       │
│   201 │   │   │   │   )                                                      │
│   202 │   │   elif route_handler.has_sync_callable:                          │
│ ❱ 203 │   │   │   data = route_handler.fn(**parsed_kwargs)                   │
│   204 │   │   else:                                                          │
│   205 │   │   │   data = await route_handler.fn(**parsed_kwargs)             │
│   206                                                                        │
│                                                                              │
│ /Users/jderrien/projects/litestar/tests/unit/test_middleware/test_exception_ │
│ handler_middleware.py:310 in handler                                         │
│                                                                              │
│   307 def test_traceback_truncate_struct_logging() -> None:                  │
│   308 │   @get("/test")                                                      │
│   309 │   def handler() -> None:                                             │
│ ❱ 310 │   │   raise ValueError("Test debug exception")                       │
│   311 │                                                                      │
│   312 │   app = Litestar([handler], logging_config=StructLoggingConfig(log_e │
│   313                                                                        │
╰──────────────────────────────────────────────────────────────────────────────╯
ValueError: Test debug exception

Closes

Closes #3228

@jderrien jderrien requested review from a team as code owners May 17, 2024 10:24
Copy link

codecov bot commented May 17, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Please upload report for BASE (main@5acf84b). Learn more about missing BASE report.

Additional details and impacted files
@@           Coverage Diff           @@
##             main    #3507   +/-   ##
=======================================
  Coverage        ?   98.28%           
=======================================
  Files           ?      328           
  Lines           ?    14848           
  Branches        ?     2358           
=======================================
  Hits            ?    14593           
  Misses          ?      116           
  Partials        ?      139           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@jderrien jderrien force-pushed the fix-exceptions-logged-twice branch from af04969 to a2b292a Compare May 17, 2024 10:42
@peterschutt
Copy link
Contributor

which implies small breaking changes.

Can you ELI5 these please?

@jderrien
Copy link
Contributor Author

@peterschutt Basically, that's what I tried to do with the ⚠️ icons. It also depends what you define as a breaking change.

To sum up:

  • Update of type ExceptionLoggingHandler and signature of handle_exception_logging() might break custom exception_logging_handler. This is the main breaking change.
  • Update of log messages might break some tooling.
  • For structlog, the field traceback is removed. It might break some tooling too.
  • Adding None as a possible value to traceback_line_limit, and also as the default value, might break something.

@peterschutt
Copy link
Contributor

@peterschutt Basically, that's what I tried to do with the ⚠️ icons. It also depends what you define as a breaking change.

To sum up:

* Update of type `ExceptionLoggingHandler` and signature of `handle_exception_logging()` might break custom `exception_logging_handler`. This is the main breaking change.

* Update of log messages might break some tooling.

* For structlog, the field `traceback` is removed. It might break some tooling too.

* Adding `None` as a possible value to `traceback_line_limit`, and also as the default value, might break something.

Thanks for that. I think this means you'd need to point this at the v3 branch, unless you think there's a way you can do this in a non-breaking way.

However, on the topic of pointing this as v3, you should also read #2858

@jderrien
Copy link
Contributor Author

@peterschutt Thank you for pointing me to this issue. Is there a timeline for a v3 realase?

In fact, I have this PR but I also started working on other improvements on another branch a while ago. So I'm wondering if it's worth to continue the work. If v2 is still around for some months (like 4+ months), I think it might be worth.

I think this means you'd need to point this at the v3 branch, unless you think there's a way you can do this in a non-breaking way.

I can probably rollback the change on ExceptionLoggingHandler / handle_exception_logging(). But the other changes are problematic too? I mean, having traceback for structlog doesn't make sense since exception is logged. It's just increasing the log size for nothing.

My take: When you discover a new framework, you generally start a new project and one of the first tasks is to setup the logging. The current state of litestar logging doesn't inspire trust in the framework. So it might be interesting to solve what can be easily solved, maybe at the cost of minor breaking changes. And if v3 can get rid of the logging complexity in the future, it would be even better.

@peterschutt
Copy link
Contributor

@peterschutt Thank you for pointing me to this issue. Is there a timeline for a v3 realase?

No timeline at this point.

In fact, I have this PR but I also started working on other improvements on another branch a while ago. So I'm wondering if it's worth to continue the work. If v2 is still around for some months (like 4+ months), I think it might be worth.

V2 will still be around for a long time, we'll continue to support it just as we currently support V1 (aka starlite). V2 will go into maintenance mode once V3 is out.

I think this means you'd need to point this at the v3 branch, unless you think there's a way you can do this in a non-breaking way.

I can probably rollback the change on ExceptionLoggingHandler / handle_exception_logging(). But the other changes are problematic too? I mean, having traceback for structlog doesn't make sense since exception is logged. It's just increasing the log size for nothing.

My take: When you discover a new framework, you generally start a new project and one of the first tasks is to setup the logging. The current state of litestar logging doesn't inspire trust in the framework. So it might be interesting to solve what can be easily solved, maybe at the cost of minor breaking changes. And if v3 can get rid of the logging complexity in the future, it would be even better.

Perhaps we should bite the bullet and deprecate the use of LoggingConfig in the next minor release? And at the same time, replace the usage documentation for logging with examples of how to configure popular logging libraries alongside litestar. It would be a step in the direction of #2858 (comment), without yet making changes that would break existing code.

@jderrien
Copy link
Contributor Author

jderrien commented May 18, 2024

Perhaps we should bite the bullet and deprecate the use of LoggingConfig in the next minor release? And at the same time, replace the usage documentation for logging with examples of how to configure popular logging libraries alongside litestar. It would be a step in the direction of #2858 (comment), without yet making changes that would break existing code.

Yep, I read #2858 (comment) and that's what I was refering to in my previous message. I already had the same feeling.

But I feel like deprecating LoggingConfigright now is more work for both maintainers and users. So if it was me, I would probably keep that for v3.

I think that what I call "small breaking changes" here are easy to adapt for the minority of users impacted (who should be familiar with LoggingConfig). And it improves things for everyone (decrease log size, exceptions more readable, small bug fixes, etc).

Despite of the complexity behind LoggingConfig, it's customizable enough. Overall it does the job, so it could be kept around in v2. But new users shouldn't have to dive into this complexity at the beginning of their journey with Litestar.

When I discovered Litestar and started a project a few weeks ago, with Python 3.12, the queue_listener handler was broken, the exceptions are not displayed by default, I had to read the docs, search for github issues, dig into the litestar codebase to understand what was going on. Then I discovered exceptions were logged twice and the framework was trying to limit the size of the stacktraces. Finally I worked on #3185. It was interesting but also quite hard and time consuming.

According to #3482 I'm not the only one to struggle.

So my main goal is just to get decent logging defaults out of the box for new users. I fixed the queue_listener handler in #3185. There is this PR. And then I plan to open another one (see this branch: https://github.com/jderrien/litestar/tree/logging-improvements).

Depending on your final decision, I could continue this work and we could make a single release with all these logging breaking changes (but trying to limit them). Or I could stop the work around this subject.

Just let me know :)

@peterschutt
Copy link
Contributor

Perhaps we should bite the bullet and deprecate the use of LoggingConfig in the next minor release? And at the same time, replace the usage documentation for logging with examples of how to configure popular logging libraries alongside litestar. It would be a step in the direction of #2858 (comment), without yet making changes that would break existing code.

Yep, I read #2858 (comment) and that's what I was refering to in my previous message. I already had the same feeling.

But I feel like deprecating LoggingConfigright now is more work for both maintainers and users. So if it was me, I would probably keep that for v3.

If we are to make the proposed changes in v3, the current behavior must be deprecated in v2 - the functionality won't go away, we just wouldn't be suggesting its use.

When I discovered Litestar and started a project a few weeks ago, with Python 3.12, the queue_listener handler was broken, the exceptions are not displayed by default, I had to read the docs, search for github issues, dig into the litestar codebase to understand what was going on. Then I discovered exceptions were logged twice and the framework was trying to limit the size of the stacktraces. Finally I worked on #3185. It was interesting but also quite hard and time consuming.

To me, this is another indicator that this facet of our code base should be deprecated, and removed. If so many surface-level issues are present, how much could the feature possibly be in use in the wild? I for one don't use it.

According to #3482 I'm not the only one to struggle.

So my main goal is just to get decent logging defaults out of the box for new users. I fixed the queue_listener handler in #3185. There is this PR. And then I plan to open another one (see this branch: https://github.com/jderrien/litestar/tree/logging-improvements).

Depending on your final decision, I could continue this work and we could make a single release with all these logging breaking changes (but trying to limit them). Or I could stop the work around this subject.

Just let me know :)

@litestar-org/maintainers - any input here?

@provinzkraut
Copy link
Member

To me, this is another indicator that this facet of our code base should be deprecated, and removed. If so many surface-level issues are present, how much could the feature possibly be in use in the wild? I for one don't use it.

I agree with you on this. Our current logging config tries to do way to much, i.e. being a one-stop shop to configure various different logging libraries for different scenarios, with no real benefit. We don't need to be able to configure all of this just to get access to a logger anywhere in Litestar, and it would probably best if we leave this all up to the user.

@jderrien
Copy link
Contributor Author

jderrien commented May 19, 2024

@provinzkraut While we agree on this, the question now is about this PR and the future one I might open.

To sum up, LoggingConfig will have to stay here for a while, even if you decide to deprecate it, as @peterschutt said. It will take time before being able to remove it completly. So would you accept my fixes at the cost of minor breaking changes? My opinion is it will benefit to new users and improve things for existing ones.

Here are the breaking changes I have mentioned for this PR in a previous comment, with more context (in bold):

  • Update of type ExceptionLoggingHandler and signature of handle_exception_logging() might break custom exception_logging_handler. This is the main breaking change. This might be reverted
  • Update of log messages might break some tooling. This improves readability & logging gets more aligned with structlog
  • For structlog, the field traceback is removed. It might break some tooling too. But it will primarily decrease log size (important in production) and improves readability
  • Adding None as a possible value to traceback_line_limit, and also as the default value, might break something. The signature gets updated. Tracebacks are no more truncated by default (having currently 2 stacktraces, a full one and a "possibly truncated" one, doesn't make sense). For structlog, this option would be deprecated (more infos in the description).

@github-actions github-actions bot removed the area/types This PR involves changes to the custom types label May 24, 2024
@provinzkraut
Copy link
Member

Hey @jderrien, sorry for the delay here.

So would you accept my fixes at the cost of minor breaking changes?

As @peterschutt pointed out, if there are breaking changes, even if they are minor, we can't have this go into 2.x. Maybe there is a way to make these things non-breaking somehow.

Update of type ExceptionLoggingHandler and signature of handle_exception_logging() might break custom exception_logging_handler. This is the main breaking change. This might be reverted

This seems to have been reverted already.

Update of log messages might break some tooling. This improves readability & logging gets more aligned with structlog

I think this is not that problematic and might go in. I'm not sure whether we consider the exact wording of log messages part of the public API and therefore changes to them breaking, but I'm inclined to say this is not the case.

For structlog, the field traceback is removed

Is this necessary? From what I understand, this just tidies things up a bit. So while I'd prefer not introducing any more configuration, maybe this is the way to go? Add a flag to exclude it, and have it off by default. Removing the traceback could be a major breaking change IMO if people rely on it.

Adding None as a possible value to traceback_line_limit

Maybe this one could be fixed by using e.g. -1 to indicate the same behaviour as None. Not ideal, but it wouldn't break anything.


With all these alterations in place, would you say this PR still accomplished its goal? If so, I'd be okay with having it go in like that.

@jderrien jderrien force-pushed the fix-exceptions-logged-twice branch 3 times, most recently from c830a4e to ecd80be Compare May 27, 2024 16:25
@jderrien
Copy link
Contributor Author

Hey @provinzkraut,

I've update the PR. No more breaking changes in the API.


About removing traceback:

Is this necessary? From what I understand, this just tidies things up a bit.

I'd say this is necessary since #3228 is "exceptions are logged twice". So we have to remove this field for structlog to fix the issue. The full stacktrace was and is still logged in the exception field.

AFAIK, it might break some external tool setup (i.e. log parsing). But this is almost the same risk as updating the wording of log messages. So not really a breaking change (?).

In the end, this is easy to update for users. I think the release note should just make it clear.

The outcome is:

  • Reduce the log size for everyone, which is important in production environments
  • Improve the developper experience (logs are easier to read in development, and new users don't have to dig too much into the logging to get a proper config)

I don't think we should wait v3 release to fix that.


About adding None as a possible value to traceback_line_limit:

I've reverted it. And I wasn't comfortable with keeping the feature in the standard logging config while removing it in the structlog one.
So default value is now -1 in both cases, and any other value is ignored and will show a deprecation warning.

I'm wondering if a deprecation warning is enough (since they're masked by default)?


For a possible release, if I don't miss anything, the outline might be:

Exception logging:

  • The wording of the log message has been updated
  • For structlog, the traceback field in the log message (which contained a truncated stacktrace) has been removed. The exception field already contains the full stacktrace.
  • The option traceback_line_limit has been deprecated, the value is now ignored, the full stacktrace will be logged

litestar/logging/config.py Outdated Show resolved Hide resolved
litestar/logging/config.py Outdated Show resolved Hide resolved
litestar/logging/config.py Outdated Show resolved Hide resolved
@provinzkraut
Copy link
Member

Thanks for the effort @jderrien!

This is good to go in from my side. The coverage decrease is expected since you're deleting tests, so that can be ignored!

@jderrien jderrien force-pushed the fix-exceptions-logged-twice branch from 8dcabb8 to b85fc38 Compare May 30, 2024 08:30
@jderrien jderrien force-pushed the fix-exceptions-logged-twice branch from b85fc38 to 4b1c1fd Compare May 30, 2024 08:33
@jderrien jderrien changed the title fix(logging)!: do not log exceptions twice & fix pretty_print_tty fix(logging): do not log exceptions twice, deprecate traceback_line_limit and fix pretty_print_tty May 30, 2024
@jderrien jderrien force-pushed the fix-exceptions-logged-twice branch from 4b1c1fd to a6338ba Compare May 30, 2024 08:41
Copy link

Documentation preview will be available shortly at https://litestar-org.github.io/litestar-docs-preview/3507

@provinzkraut provinzkraut merged commit 972ee67 into litestar-org:main May 30, 2024
26 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Bug: exceptions are logged twice
4 participants