Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
2 tasks done
egberts opened this issue Jul 1, 2024 · 5 comments

Comments

@egberts
Copy link

egberts commented Jul 1, 2024

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

Copy link

github-actions bot commented Jul 1, 2024

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
Copy link
Author

egberts commented Jul 1, 2024

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
Copy link
Author

egberts commented Jul 1, 2024

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
Copy link
Contributor

aidaco commented Jul 1, 2024

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
Copy link
Contributor

aidaco commented Jul 2, 2024

Related discussion at PR #3233

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants