Log to stderr without breaking progress bars

[ewels]

Hello!

I've run into a problem with rich logging + rich progress bars. I want log messages to be sent to STDERR instead of STDOUT, so that the tool results can be easily piped to a file without being contaminated by log messages. I've been doing this for a while now by using a custom console and it works well. However, doing this seems to break the nice behaviour that Rich has of moving the progress bar below log messages.

Minimal example:

import logging
from rich.console import Console
from rich.logging import RichHandler
from rich.progress import track
import time

logging.basicConfig(
    level="NOTSET", handlers=[RichHandler(console=Console(stderr=True))]
)
log = logging.getLogger()

for n in track(range(5), description="Processing..."):
    log.info(f"Working.. {n}")
    time.sleep(0.2)

$ python rich_log_stderr.py
Processing... ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━   0% -:--:--[06/28/21 09:30:22] INFO     INFO:root:Working.. 0      rich_log_stderr.py:13
Processing... ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━   0% -:--:--                    INFO     INFO:root:Working.. 1      rich_log_stderr.py:13
Processing... ━━━━━━━━╺━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━  20% -:--:--                    INFO     INFO:root:Working.. 2      rich_log_stderr.py:13
Processing... ━━━━━━━━━━━━━━━━╺━━━━━━━━━━━━━━━━━━━━━━━  40% 0:00:01                    INFO     INFO:root:Working.. 3      rich_log_stderr.py:13
Processing... ━━━━━━━━━━━━━━━━━━━━━━━━╺━━━━━━━━━━━━━━━  60% 0:00:01                    INFO     INFO:root:Working.. 4      rich_log_stderr.py:13
Processing... ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00

If I remove the console=Console(stderr=True) then it works fine:

$ python rich_log_simple.py
[06/28/21 09:29:59] INFO     INFO:root:Working.. 0      rich_log_simple.py:11
                    INFO     INFO:root:Working.. 1      rich_log_simple.py:11
[06/28/21 09:30:00] INFO     INFO:root:Working.. 2      rich_log_simple.py:11
                    INFO     INFO:root:Working.. 3      rich_log_simple.py:11
                    INFO     INFO:root:Working.. 4      rich_log_simple.py:11
Processing... ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00

...but then, logs go to STDERR.

Any ideas how I can get around this?

Thanks in advance,

Phil

[ewels]

Ok, had a "duh" moment this morning when it clicked that this is because the log messages and progress bar are using different consoles.

If we create a Console instance and then use it for both the log messages and the progress bar, it works fine:

import logging
from rich.console import Console
from rich.logging import RichHandler
from rich.progress import track
import time

myconsole = Console(stderr=True)
logging.basicConfig(level="NOTSET", handlers=[RichHandler(console=myconsole)])
log = logging.getLogger()

for n in track(range(5), description="Processing...", console=myconsole):
    log.info(f"Working.. {n}")
    time.sleep(0.2)

Solved! Thanks for the rubber-duck treatment! 🦆 😀

[willmcgugan]

Aha! Marvelous. 😄