TRY400 flags log.error() + raise/sys.exit()

[jankatins]

In the following code snippet, a TRY400 violation is raised because I use log.error() and not log.exception() in an exception handler. In this case it's by design as I immediately re-raise the exception, I just want to add some message to the exception and I don't want the stacktrace shown twice.

import logging
log = logging.get_logger(__name__)
# The outer app loop...
try:
    # actually some function call which can't handle the error but wants to abort...
    try:
        raise Exception("bad")
    except Exception:
        # to get some info into the log to "enrich" it...
        # and I don't want to see the exception stacktrace twice
        log.error("That might mean ..." ) # noqa: TRY400: use log.exception()
        raise
except Exception:
    log.exception("Caught unhandled exception in outer context")

In my opinion the pattern "in except block, with a log.something + 'raise' in all cases` should be something TRY400 should ignore/be ok with.

[tjkuson]

Is there a reason why you couldn't pass exc_info=False into the log.exception method to suppress the stacktrace?

[jankatins]

Mostly because I didn't know of it :-) but also because I wanted a different log level than EXCEPTION.

[dhruvmanila]

If you're using Python 3.11, then you should use the new add_notes feature to enhance the message.

I wanted a different log level than EXCEPTION.

Is this a custom defined log level as it doesn't exists in the logging module?

Correct me if I'm wrong as I might not be aware of the context, but I think you could get away with just using logging.exception. Whatever message you pass in logging.exception is logged at ERROR level and in addition to that the traceback is printed as well. You could provide the additional message and have the traceback message in the logs as well. Example:

def foo():
	def bar():
		try:
			raise Exception("exception message")
		except:
			logging.exception("additional message")
	bar()


foo()
# ERROR:root:additional message
# Traceback (most recent call last):
#   File "<ipython-input-7-78c777a5f655>", line 4, in bar
#     raise Exception("exception message")
# Exception: exception message

[jankatins]

Whatever message you pass in logging.exception is logged at ERROR level

Wow, thanks, I didn't know that. Always though that exception is it's own level.

re add_notes: Yes, I think that would be nice, but I haven't checked how this is then displayed in the logs. It's really nice that one has a extra log line with just the extra info instead of the "log lines explosion" of the stacktrace...

Anyway: I still think this pattern should be not flagged: it's perfectly good code to use e.g. log.info("message") or whatever else is printed...

[saippuakauppias]

If you disable the sending of information about the exception with exc_info=False - there is another error: TRY401 Redundant exception object included in logging.exception call:

import logging


logger = logging.getLogger('stream.logger')


def foo():
    try:
        raise ValueError('error message')
    except Exception as e:
        logger.error('Found handled error: %s', e)
        logger.error('Found handled error: %s', e, exc_info=False)
        logger.exception('Found handled error: %s', e, exc_info=False)
        logger.exception('Found handled error: %s', str(e), exc_info=False)

$ ruff "ruff_errors/TRY400.py" --select=TRY400,TRY401
ruff_errors/TRY400.py:11:9: TRY400 Use `logging.exception` instead of `logging.error`
ruff_errors/TRY400.py:12:9: TRY400 Use `logging.exception` instead of `logging.error`
ruff_errors/TRY400.py:13:53: TRY401 Redundant exception object included in `logging.exception` call
ruff_errors/TRY400.py:14:57: TRY401 Redundant exception object included in `logging.exception` call
Found 4 errors.

I agree that it is often necessary to log only text without traceback using the .error() method

[saippuakauppias]

But in this case the log will also be traceback, and I do not need it

[charliermarsh]

Hm, I guess if exc_info is set to False, we shouldn't raise "Redundant exception object included in call".

[charliermarsh]

Similarly, "Redundant exception object included in call" should be enforced when we log error with exc_info=True (right now, it only logs on exception).

[dhruvmanila]

Similarly, "Redundant exception object included in call" should be enforced when we log error with exc_info=True (right now, it only logs on exception).

I believe this should be true for all other log levels as the exc_info parameter is common to all function calls. Additionally, the parameter can also accept exception instances along with a tuple returned by sys.exc_info:

In [4]: try:
   ...:     raise ValueError("some error")
   ...: except ValueError as exc:
   ...:     logging.warning("Error raised: %s", exc, exc_info=exc)
   ...: 
WARNING:root:Error raised: some error
Traceback (most recent call last):
  File "<ipython-input-4-1428f1d5d721>", line 2, in <module>
    raise ValueError("some error")
ValueError: some error

In [5]: try:
   ...:     raise ValueError("some error")
   ...: except ValueError as exc:
   ...:     logging.warning("Error raised: %s", exc, exc_info=True)
   ...: 
WARNING:root:Error raised: some error
Traceback (most recent call last):
  File "<ipython-input-5-998582a3cfed>", line 2, in <module>
    raise ValueError("some error")
ValueError: some error

In [7]: try:
   ...:     raise ValueError("some error")
   ...: except ValueError as exc:
   ...:     import sys
   ...:     logging.warning("Error raised: %s", exc, exc_info=sys.exc_info())
   ...: 
WARNING:root:Error raised: some error
Traceback (most recent call last):
  File "<ipython-input-7-7998fc845097>", line 2, in <module>
    raise ValueError("some error")
ValueError: some error

Reference: https://docs.python.org/3/library/logging.html?highlight=logging#logging.Logger.debug

[zanieb]

For what it's worth, I agree logger.exception is not correct to suggest if you are going to raise the exception after and do not want to log the stack trace. In the same way that we suggest you should use logger.exception to set exc_info=True, you should use logger.error to set exc_info=False. Using logger.exception then opting back out of exc_info is weird.

In part, I may have qualms with TRY400 itself. If I do logger.error("foo", exc_info=True) it should be corrected to logger.exception("foo") but it is pretty common to want to write error logs in an exception handler without including the stack trace. Is there another rule that just covers that narrower conversion?

[jankatins]

Another bad case: when the log is followed by a sys.exit():

# In an optional script
try:
    import ....
except ImportError:
    msg = "Dependencies are missing: run `poetry install --with <dependency group> --sync`"
    logger.error(msg) # noqa: TRY400
    sys.exit(1)

I specifically do NOT want the whole stacktrace here because it makes figuring out what to do harder than just seeing the specific instruction here.

[bcyran]

I just want to say that I wholeheartedly agree with @zanieb's stance on this. TRY400 should not be reported for exceptions which are immediately re-raised. It would be very nice to see this issue picked up again.