[BUG] live displays and console printing are not thread safe

[GBeauregard]

There seems to be some sort of threading/race issue with the console and the rich handler (or maybe with live dislays in general?) that causes log lines to get lost or misplaced when used with live displays or status displays.

To Reproduce
Here's a code example that will print out the logs from a queue in a separate thread. Note the log lines aren't then all expected to be above the status, but I was expecting the status to not interfere with it if it's thread safe. In particular the status isn't even getting properly wiped here.

import atexit
import logging
import logging.handlers
import queue

import rich.logging
import rich.console

logger = logging.getLogger(__name__)
console = rich.console.Console()

root_logger = logging.getLogger("")
rhandler = rich.logging.RichHandler(console=console)
que = queue.Queue()
queue_handler = logging.handlers.QueueHandler(que)
listener = logging.handlers.QueueListener(que, rhandler)
root_logger.addHandler(queue_handler)
listener.start()
atexit.register(lambda x: x.stop(), listener)

with console.status("testing"):
    for n in range(1000):
        logger.error(n)

With this a variety of things can happen, the status can get leftover in a line printed at the same time as a log message or sometimes it can even eat a log message entirely.

Here's an example where it ate a line entirely

a lot of the time I get other goofy stuff like this

Platform
Gentoo Linux / kitty 0.23.1

Diagnose

pyffstream ❯ python -m rich.diagnose
python -m rich._windows
pip freeze | grep rich
╭───────────────────────── <class 'rich.console.Console'> ─────────────────────────╮
│ A high level console interface.                                                  │
│                                                                                  │
│ ╭──────────────────────────────────────────────────────────────────────────────╮ │
│ │ <console width=147 ColorSystem.TRUECOLOR>                                    │ │
│ ╰──────────────────────────────────────────────────────────────────────────────╯ │
│                                                                                  │
│     color_system = 'truecolor'                                                   │
│         encoding = 'utf-8'                                                       │
│             file = <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'> │
│           height = 41                                                            │
│    is_alt_screen = False                                                         │
│ is_dumb_terminal = False                                                         │
│   is_interactive = True                                                          │
│       is_jupyter = False                                                         │
│      is_terminal = True                                                          │
│   legacy_windows = False                                                         │
│         no_color = False                                                         │
│          options = ConsoleOptions(                                               │
│                        size=ConsoleDimensions(width=147, height=41),             │
│                        legacy_windows=False,                                     │
│                        min_width=1,                                              │
│                        max_width=147,                                            │
│                        is_terminal=True,                                         │
│                        encoding='utf-8',                                         │
│                        max_height=41,                                            │
│                        justify=None,                                             │
│                        overflow=None,                                            │
│                        no_wrap=False,                                            │
│                        highlight=None,                                           │
│                        markup=None,                                              │
│                        height=None                                               │
│                    )                                                             │
│            quiet = False                                                         │
│           record = False                                                         │
│         safe_box = True                                                          │
│             size = ConsoleDimensions(width=147, height=41)                       │
│        soft_wrap = False                                                         │
│           stderr = False                                                         │
│            style = None                                                          │
│         tab_size = 8                                                             │
│            width = 147                                                           │
╰──────────────────────────────────────────────────────────────────────────────────╯
platform="Linux"
WindowsConsoleFeatures(vt=False, truecolor=False)
rich==10.11.0

[GBeauregard]

Here's another example showing the same problem happens with regular console printing.

import threading

import rich.console

console = rich.console.Console()


def count_to_n(n):
    for i in range(n):
        console.print(i)


with console.status("testing"):
    thread = threading.Thread(target=count_to_n, args=(100,))
    thread.start()

[GBeauregard]

Here's another example showing it affects live displays more generally.

import threading

import rich.console
import rich.live

console = rich.console.Console()


def count_to_n(n):
    for i in range(n):
        console.print(i)


with rich.live.Live("test", console=console, refresh_per_second=20, transient=True):
    thread = threading.Thread(target=count_to_n, args=(100,))
    thread.start()

[GBeauregard]

Do you have a recommended workaround to enable in a debug mode? (is there a console-level setting that removes the live refresh behavior or something?)

I've been trying to imagine ways to monkey patch this for a workaround, but the thread race being during live display close makes it a bit awkward. Are there any locks in the internal API I can use?

[Alex7Li]

Hi, I looked at this problem this weekend and found an ok fix. Basically, the console and the live have two separate locks, and they need to share the same lock to have any chance of dealing with the concurrency. So I made them share that lock and also threw a bunch more code under the locks and now it works. I can make a PR for this as well if the maintainer is ok with it. Not sure how to make a test that proves it fixes anything, though.

master...Alex7Li:master

[GBeauregard]

Nice @Alex7Li, rich compatibility with concurrency is a major upgrade 👍

[GBeauregard]

carrying this patch and the typing bug fixes in a temporary repo I can set as a dependency since I was short-sighted enough to design my app around concurrency before I confirmed if rich supported threading 🤦 https://github.com/GBeauregard/rich-threads/

[willmcgugan]

There is a thread safety mechansim in the Console, but it's not entirely based on locks. Each thread has a separate buffer which it writes in to when in the Console context manager. An exclusive lock is only required when writing to the file.

Something is clearly going wrong in combination with Live. Sharing the lock with Live and Console would "fix" it, but it's not an optimal solution.

@GBeauregard Your examples may be something different. You don't join the threads within the Live context, which means they exit almost immediately. Suspect that's a different issue.

It's on my list, I'll take a deep dive on this issue(s) soon.

[GBeauregard]

@willmcgugan to clarify, this was intentional (to recreate a race condition that occurs during closure of the Live context). This causes stuff to get omitted/broken in the app I wrote almost constantly because of how I wrote it threaded.

My current workaround is to just print any important temporary debug messages 4 or 5 times to try to make sure it won't get overwritten 😄

[github-actions]

Did I solve your problem?

Consider sponsoring the ongoing work on Rich and Textual.

Or buy me a coffee to say thanks.

– Will McGugan

[GBeauregard]

@darrenburns @willmcgugan if it is okay I would like to open a new bug to track this so I can get notifications for it

(the bugfix for this was reverted due to problems; this bug is still open)