[BUG] Using `my_python_executable | head` caused a cascading error due to ignoring SIGPIPE error condition

[egberts]

• I've checked docs and closed issues for possible solutions.
• I can't find my issue in the FAQ.

When UNIX piping its output into a head executable, it outputs the next 10 line, then starts returning back a traceback for each log output.

Otherwise, ideally, one would expect the head to close the PIPE and the application switch over to /dev/null for all lines after the first 10 lines as shown below:

$ my_test_code.py | head
<first 10-line of output goes here>

<read should be silent, then exit>
$

Ideally, such SIGPIPE or close condition due to PIPE should be silently switching over to /dev/null on the remainder of its execution time after a file-connection-closed condition.

Actually sends a traceback dump for every logger line until its completion.

The first Traceback is unique from the rest and has RichHandler-related error.

Traceback (most recent call last):
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/logging.py", line 170, in emit
    self.console.print(log_renderable)
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 1673, in print
    with self:
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 865, in __exit__
    self._exit_buffer()
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 823, in _exit_buffer
    self._check_buffer()
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 2065, in _check_buffer
    self.file.flush()

then subsequential traceback shows application-specific errors with little or no RichHandler-related errors:

BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/user/admin/websites/example.test/debug-table/./pelican", line 32, in <module>
    sys.exit(main())
  File "/home/user/admin/websites/example.test/pelican/pelican/__init__.py", line 678, in main
    pelican.run()
  File "/home/user/admin/websites/example.test/pelican/pelican/__init__.py", line 143, in run
    p.generate_output(writer)
  File "/home/user/admin/websites/example.test/pelican/pelican/generators.py", line 822, in generate_output
    self.generate_feeds(writer)
  File "/home/user/admin/websites/example.test/pelican/pelican/generators.py", line 338, in generate_feeds
    writer.write_feed(
  File "/home/user/admin/websites/example.test/pelican/pelican/writers.py", line 171, in write_feed
    logger.info("Writing %s", complete_path)
  File "/usr/lib/python3.11/logging/__init__.py", line 1489, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 978, in handle
    self.emit(record)
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/logging.py", line 172, in emit
    self.handleError(record)
Message: 'Writing %s'
Arguments: ('/home/user/admin/websites/example.test/debug-table/output/feeds/atom.xml',)
--- Logging error ---
Traceback (most recent call last):
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/logging.py", line 170, in emit
    self.console.print(log_renderable)
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 1673, in print
    with self:
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 865, in __exit__
    self._exit_buffer()
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 823, in _exit_buffer
    self._check_buffer()
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/console.py", line 2065, in _check_buffer
    self.file.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/user/admin/websites/example.test/debug-table/./pelican", line 32, in <module>
    sys.exit(main())
  File "/home/user/admin/websites/example.test/pelican/pelican/__init__.py", line 678, in main
    pelican.run()
  File "/home/user/admin/websites/example.test/pelican/pelican/__init__.py", line 143, in run
    p.generate_output(writer)
  File "/home/user/admin/websites/example.test/pelican/pelican/generators.py", line 822, in generate_output
    self.generate_feeds(writer)
  File "/home/user/admin/websites/example.test/pelican/pelican/generators.py", line 346, in generate_feeds
    writer.write_feed(
  File "/home/user/admin/websites/example.test/pelican/pelican/writers.py", line 171, in write_feed
    logger.info("Writing %s", complete_path)
  File "/usr/lib/python3.11/logging/__init__.py", line 1489, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.11/logging/__init__.py", line 978, in handle
    self.emit(record)
  File "/home/user/virtualenvs/pelican/lib/python3.11/site-packages/rich/logging.py", line 172, in emit
    self.handleError(record)

The minimal code example that demonstrates the issue is my_test_code.py file, its UNIX file mode set as an executable and is given below:

import os

from rich.console import Console
from rich.logging import RichHandler
import logging

level = 3
console = Console()
try:
    terminal_width = os.get_terminal_size()
    if terminal_width < 80:
        terminal_width = 80
except:
    terminal_width = 80
DEFAULT_LOG_HANDLER = RichHandler(console=console, locals_max_length=terminal_width)
LOG_FORMAT = "%(message)s"
LOG_FORMAT = "%(name)s: %(message)s"
logging.basicConfig(
    level=logging.DEBUG,
    format=LOG_FORMAT,
    datefmt="[%H:%M:%S]",
    handlers=[DEFAULT_LOG_HANDLER] if DEFAULT_LOG_HANDLER else [],
)
logger = logging.getLogger('mymain')
logger.setLevel(level)

logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
print(logger.parent)
logger = logging.getLogger('spam_application.auxiliary.Auxiliary')


def sublogger():
    subbylogger = logging.getLogger("sublogger")
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.critical('did I get the sublogger\'s name?')
    subbylogger.info('creating an instance of Auxiliary')


logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
logger.critical('this should be main, before')
sublogger()
logger.critical('this should be main, after')

Platform

Click to expand

Platform

• OS version and name: Linux 6.1.0-21-amd64 SMP PREEMPT_DYNAMIC Debian 6.1.90-1 (2024-05-03) x86_64 GNU/Linux
• Python version: 3.11.2
• Pelican version: HEAD (513abbf)
• Link to theme: m.css
• Links to plugins: pelican-plugins
• Link to your site: n/a
• Link to your source: n/a

╭───────────────────────── <class 'rich.console.Console'> ─────────────────────────╮
│ A high level console interface. │
│ │
│ ╭──────────────────────────────────────────────────────────────────────────────╮ │
│ │ │ │
│ ╰──────────────────────────────────────────────────────────────────────────────╯ │
│ │
│ color_system = 'truecolor' │
│ encoding = 'utf-8' │
│ file = <_io.TextIOWrapper name='' mode='w' encoding='utf-8'> │
│ height = 26 │
│ 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=128, height=26), │
│ legacy_windows=False, │
│ min_width=1, │
│ max_width=128, │
│ is_terminal=True, │
│ encoding='utf-8', │
│ max_height=26, │
│ justify=None, │
│ overflow=None, │
│ no_wrap=False, │
│ highlight=None, │
│ markup=None, │
│ height=None │
│ ) │
│ quiet = False │
│ record = False │
│ safe_box = True │
│ size = ConsoleDimensions(width=128, height=26) │
│ soft_wrap = False │
│ stderr = False │
│ style = None │
│ tab_size = 8 │
│ width = 128 │
╰──────────────────────────────────────────────────────────────────────────────────╯
╭─── <class 'rich._windows.WindowsConsoleFeatures'> ────╮
│ Windows features available. │
│ │
│ ╭───────────────────────────────────────────────────╮ │
│ │ WindowsConsoleFeatures(vt=False, truecolor=False) │ │
│ ╰───────────────────────────────────────────────────╯ │
│ │
│ truecolor = False │
│ vt = False │
╰───────────────────────────────────────────────────────╯
╭────── Environment Variables ───────╮
│ { │
│ 'TERM': 'xterm-256color', │
│ 'COLORTERM': 'truecolor', │
│ 'CLICOLOR': None, │
│ 'NO_COLOR': None, │
│ 'TERM_PROGRAM': None, │
│ 'COLUMNS': None, │
│ 'LINES': None, │
│ 'JUPYTER_COLUMNS': None, │
│ 'JUPYTER_LINES': None, │
│ 'JPY_PARENT_PID': None, │
│ 'VSCODE_VERBOSE_LOGGING': None │
│ } │
╰────────────────────────────────────╯
platform="Linux"
rich==13.7.1

[github-actions]

Thank you for your issue. Give us a little time to review it.

PS. You might want to check the FAQ if you haven't done so already.

This is an automated reply, generated by FAQtory

[egberts]

This error condition occurred inside both xterm terminal (whose Python os.get_terminal_width() functionally works) and virtual consoles inside both PyCharm/VSCode (where Python's os.get_terminal_width() does not work at all).

[egberts]

After taking out the handler=RichHandler() out from the logging.basicConfig(), no more errant tracekbacks, UNIX pipe is normally reshunted into /dev/null.

$ # 2>&1 is used to fold the logging's default stderr into the stdout.
$ python logme.py 2>&1 | head
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
spam_application.auxiliary.Auxiliary: this should be main, before
sublogger: did I get the sublogger's name?

[aidaco]

This probably isn't a good solution, but for reference I put together a modified RichHandler based on this note in the python docs. It implements the /dev/null switching that you're looking for. I think handling the BrokenPipeError would be best placed here around the self.file.write(text) in rich.console.Console._check_buffer().

import os
from logging import LogRecord

import rich.logging
from rich.traceback import Traceback
from rich._null_file import NullFile


class RichHandler(rich.logging.RichHandler):
    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,
                code_width=self.tracebacks_code_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,
                suppress=self.tracebacks_suppress,
                max_frames=self.tracebacks_max_frames,
            )
            message = record.getMessage()
            if self.formatter:
                record.message = record.getMessage()
                formatter = self.formatter
                if hasattr(formatter, "usesTime") and formatter.usesTime():
                    record.asctime = formatter.formatTime(record, formatter.datefmt)
                message = formatter.formatMessage(record)

        message_renderable = self.render_message(record, message)
        log_renderable = self.render(
            record=record, traceback=traceback, message_renderable=message_renderable
        )
        if isinstance(self.console.file, NullFile):
            # Handles pythonw, where stdout/stderr are null, and we return NullFile
            # instance from Console.file. In this case, we still want to make a log record
            # even though we won't be writing anything to a file.
            self.handleError(record)
        else:
            try:
                self.console.print(log_renderable)
            except BrokenPipeError:
                devnull = os.open(os.devnull, os.O_WRONLY)
                os.dup2(devnull, self.console.file.fileno())
                self.console.print(log_renderable)
            except Exception:
                self.handleError(record)

[aidaco]

Related discussion at PR #3233

[willmcgugan]

Fixed in main

[github-actions]

I hope we solved your problem.

If you like using Rich, you might also enjoy Textual