Custom formatters ignored in RichHandler when rich_tracebacks=True

[willmcgugan]

Hi,

I am not sure if it is a bug or intended behavior. But I configured a RichHandler with rich traceback toggled on. I also added a custom formatter to include the process name and Id in all log messages.

This works fine for all logging levels with the exception of logging exceptions/errors. Raised errors are logged nicely with rich tracebacks but the process name isn’t included in the logged error message before the traceback. It seems the configured formatter is simply ignored in this case.

This works however, if I replace the RichHandler with a normal StreamHandler. Of course I can manually add the process name to the rich handled error traceback. But if a user of our library doesn’t use rich, he would see the process name twice (once because of the formatter and once because of the manual addition).

Any feedback on this issue is much appreciated :)

Best regards
Lars

Originally posted by @LarsHill in #1072

[willmcgugan]

@LarsHill Please give v9.12.4 a try

[LarsHill]

@willmcgugan

Thanks a lot for your quick effort to fix this issue.
The current version works perfectly when a Formatter is actually provided to the RichHandler.
However, if no Formatter is provided, the traceback shows twice (once normally and once formatted).

I took the freedom to investigate the issue myself by checking the emit method in rich/logging.py.

The issue is that, no matter what, the self.format method from the logging library is called in the beginning, which formats the traceback in the standard way and includes it in the log message string.
If rich_traceback is set to true and a formatter is provided, this message gets overwritten and everything is fine. However, if no formatter is provided, the formatted message (including the traceback) is rendered together with the additional rich traceback.

I fixed this issue by including a simple else condition that handles the case of rich_traceback==True and self.formatter==False by overwriting the formatted message with the default string only message.

See below the edited emit fn:

def emit(self, record: LogRecord) -> None:
    """Invoked by logging."""
    message = self.format(record)

    traceback = None
    if (
        self.rich_tracebacks
        and record.exc_info
        and record.exc_info != (None, None, None)
    ):
        exc_type, exc_value, exc_traceback = record.exc_info
        assert exc_type is not None
        assert exc_value is not None
        traceback = Traceback.from_exception(
            exc_type,
            exc_value,
            exc_traceback,
            width=self.tracebacks_width,
            extra_lines=self.tracebacks_extra_lines,
            theme=self.tracebacks_theme,
            word_wrap=self.tracebacks_word_wrap,
            show_locals=self.tracebacks_show_locals,
            locals_max_length=self.locals_max_length,
            locals_max_string=self.locals_max_string,
        )
        if self.formatter:
            record.message = record.getMessage()
            formatter = self.formatter
            if hasattr(formatter, "usesTime") and formatter.usesTime():  # type: ignore
                record.asctime = formatter.formatTime(record, formatter.datefmt)
            message = formatter.formatMessage(record)
        else:
            message = record.getMessage()

    message_renderable = self.render_message(record, message)
    log_renderable = self.render(
        record=record, traceback=traceback, message_renderable=message_renderable
    )
    self.console.print(log_renderable)

[willmcgugan]

Should be fixed in 9.13.0

How are configuring logging so that the handler doesn't have a formatter? basicConfig seems to assign a default formatter.

[LarsHill]

Should be fixed in 9.13.0

Looks good :) I‘ll give it a try, but I guess it‘ll work now as expected.
Edit: It's fixed :)

How are configuring logging so that the handler doesn't have a formatter? basicConfig seems to assign a default formatter.

That‘s correct. But I was referring to explicitly assigning a formatter when not using basicConfig. If a handler has no formatter assigned, a default formatter will be used.
However, self.formatter is not set in this case.
For example, when using the RichHandler, I don’t necessarily have to assign a separate formatter.

Writing

import logging

from rich.logging import RichHandler


logger = logging.getLogger()
handler = RichHandler()
logger.addHandler(handler)
logger.setLevel(„INFO“)

would result in a logger that uses the default formatter. And since RichHandler inherits from Handler, self.formatter would be None.

And in rich Version 9.12.4 this scenario would lead to the double traceback rendering issue given rich_traceback is True.