Log stack traces only in debug mode #12989
Conversation
S3 Image Test Results (AMD64 / ARM64) 2 files 2 suites 8m 22s ⏱️ Results for commit ea8c0eb. ♻️ This comment has been updated with latest results. |
| @@ -1479,10 +1479,11 @@ def delete_stack(self): | |||
| # correct order yet. | |||
| continue | |||
| case OperationStatus.FAILED: | |||
| LOG.exception( | |||
| LOG.error( | |||
There was a problem hiding this comment.
suggestion: it might be nice to extract a helper method to our LOG class that we can use so we don't forget to set this behaviour in the future. E.g.
from localstack.logging import get_logger
LOG = get_logger(__name__)
LOG.error("message")which in turn is implemented like
class LocalStackLogger(logging.Logger):
def _log(self, level, *args, **kwargs):
kwargs.pop("exc_info", None)
super()._log(level, *args, **kwargs, exc_info=self.isEnabledFor(logging.DEBUG))
def exception(self, *args, **kwargs):
"""
Protect against using this method which logs the exception by default
"""
return self.error(*args, **kwargs)WDYT? Or we could write a linting rule that operates over our AST and catches usages of the LOG.error(...) without handling the exc_info field properly, or protects us against usages of LOG.exception?
There was a problem hiding this comment.
I definitely agree about the linting rule to protect about the exception usage, this is the main issue we have currently.
For the logger above, I'm not sure, or we'd instead need to override exception with a conditional exc_info instead of the default keyword exc_info=True that it has currently, so we'd be protected without changing behavior for the rest.
Also, not sure what happens when adding exc_info outside of an exception handler (except), but not anything good I suppose.
I think we'd still need to be deliberate about when we want to log stack traces or not, and always printing stack traces might be too much, it might be an exception we're actually expecting so we would not need it.
edit: it seems Ruff does not support custom linting rules though: https://docs.astral.sh/ruff/faq/#how-does-ruffs-linter-compare-to-flake8, so we might need to look into that.
There was a problem hiding this comment.
I agree, the lint rule for exception seems like a nice way here, but as Ben mentioned Ruff seems not to support custom linting rules.
On the LocalStackLogger idea, I see the point there but adding exc_info outside of an except block might not be the best option here.
9f0d066 to
c487fbf
Compare
There was a problem hiding this comment.
Awesome, nice work! 🚀
This is quite a lot of logging statements that got updated! This is good to go, I only have 2 small nits, but this can go as is. Kudos for churning through all of them!
The pipeline failure are fixed with #13004, so you can rebase and we should be good to go 👍
| if LOG.isEnabledFor(logging.DEBUG): | ||
| LOG.exception("Error executing scheduled alarm", exc_info=e) | ||
| else: | ||
| LOG.error("Error executing scheduled alarm") |
There was a problem hiding this comment.
nit: I think the previous implementation was wrong, e is an Exception here and exc_info takes a boolean.
This can be replaced by the regular one we've been using, no need for the if check.
LOG.error("Error executing scheduled alarm", exc_info=LOG.isEnabledFor(logging.DEBUG))It's not blocking, but it sends the wrong message that the Exception object needs to be based to exc_info
There was a problem hiding this comment.
As per my understanding from the official docs which mention that exc_info can accept exception instances, here, I thought we were doing that intentionally. But if it seems incorrect, I am happy to update this to the simpler version 🙂
There was a problem hiding this comment.
Ah, good catch! Let's leave it like that then 😄 this is good!
| @@ -166,7 +166,7 @@ def handle_request(request: Request, region: str) -> Response: | |||
| op = service.operation_model(service.operation_names[0]) | |||
| return serializer.serialize_error_to_response(e, op, request.headers, request_id) | |||
| except Exception as e: | |||
| LOG.exception("exception") | |||
| LOG.error("exception", exc_info=LOG.isEnabledFor(logging.DEBUG)) | |||
There was a problem hiding this comment.
nit: a bit out of scope of this PR so no need to address this, but this logging message is not going to be very useful is debug is not activated, it will just log "exception". It seems we're properly handling the exception anyway and returning a proper serialized error, so it could maybe be a debug logging statement somehow or contain more info, like LOG.error("Internal Server exception while executing SQS Query operation: '%s'", e, exc_info=LOG.isEnabledFor(logging.DEBUG)) ?
There was a problem hiding this comment.
Agreed 💯 Adding more info would definitely make it more useful 👍 As you mentioned, I will keep it as is for this PR since it is a bit out of scope for this one, but I will create a follow up PR for this 🙂
There was a problem hiding this comment.
Follow PR: #13007
c487fbf to
4aea6c0
Compare
Motivation
As a part of the initiative for improving Localstack error messages and stack traces, this PR aims to ensure that stack traces are logged when debug mode is enabled. Currently, in some use cases stack traces are logged without checking if debug mode is enabled or not. This causes excessive log noise even when
DEBUG=0.Changes
This PR cleans up logging across different use cases to ensure that stack traces are only logged when debug mode is enabled.