Skip to content

Fix OSError (BrokenPipeError) on stdout flush #6142

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 2 commits into from
Aug 27, 2024
Merged

Fix OSError (BrokenPipeError) on stdout flush #6142

merged 2 commits into from
Aug 27, 2024

Conversation

bastimeyer
Copy link
Member

@bastimeyer bastimeyer commented Aug 27, 2024 •
edited
Loading

  1. This fixes repeated errors being written to stderr whenever a new log message fails to be written to stdout due to the stream pipe being closed by the other process, e.g. when executing streamlink -l debug | head -n1. This issue is caused when trying to flush the stdout stream buffer after writing a log message. Python's logging module explicitly doesn't handle this case (for some reason).

    The fix is to simply ignore OSError (BrokenPipeError) in logging.StreamHandler.flush(). On Windows, BrokenPipeError is not raised and instead a simple OSError with errno=EINVAL.

    As an optimization, follow-up log calls could all be ignored by overriding emit() when this exception is caught for the first time, but it's not really important.

    Alternatively, the StreamHandler's handleError() method could be overridden, which is where the "--- Logging error ---" stuff is coming from, but this would remove potentially useful error messages when logging fails in a different way.

  2. The second commit fixes the broken stdout pipe raising OSError (BrokenPipeError) when the Python process exits, as Python always flushes stdout on exit.

    The fix is to destruct the sys.stdout object, as opposed to redirecting stdout to devnull, as mentioned in the SIGPIPE notes in the stdlib docs.

    There's no interference with --stdout, as there's only a simple flush at the end before calling sys.exit(...).

Only tested on my local machine. Will check later today and then merge if there are no issues.

master

$ streamlink -l debug | head -n1
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 788, in log_current_versions
    log.debug(f"Python:     {platform.python_version()}")
Message: 'Python:     3.12.4'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 789, in log_current_versions
    log.debug(f"OpenSSL:    {ssl.OPENSSL_VERSION}")
Message: 'OpenSSL:    OpenSSL 3.3.1 4 Jun 2024'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 790, in log_current_versions
    log.debug(f"Streamlink: {streamlink_version}")
Message: 'Streamlink: 6.9.0+13.g18e30397'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 794, in log_current_versions
    log.debug("Dependencies:")
Message: 'Dependencies:'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' certifi: 2024.7.4'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' isodate: 0.6.1'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' lxml: 5.3.0'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' pycountry: 24.6.1'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' pycryptodome: 3.20.0'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' PySocks: 1.7.1'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' requests: 2.32.3'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' trio: 0.26.2'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' trio-websocket: 0.11.1'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' typing-extensions: 4.12.2'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' urllib3: 2.2.2'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 915, in setup
    log_current_versions()
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 804, in log_current_versions
    log.debug(f" {name}: {version}")
Message: ' websocket-client: 1.8.0'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 916, in setup
    log_current_arguments(streamlink, parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 817, in log_current_arguments
    log.debug("Arguments:")
Message: 'Arguments:'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 916, in setup
    log_current_arguments(streamlink, parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 829, in log_current_arguments
    log.debug(f" {name}={value if name not in sensitive else '*' * 8}")
Message: ' --loglevel=debug'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 916, in setup
    log_current_arguments(streamlink, parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 829, in log_current_arguments
    log.debug(f" {name}={value if name not in sensitive else '*' * 8}")
Message: ' --player=/usr/bin/mpv'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1164, in emit
    self.flush()
  File "/usr/lib/python3.12/logging/__init__.py", line 1144, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/basti/venv/streamlink-312/bin/streamlink", line 8, in <module>
    sys.exit(main())
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 980, in main
    setup(parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 916, in setup
    log_current_arguments(streamlink, parser)
  File "/home/basti/repos/streamlink/src/streamlink_cli/main.py", line 829, in log_current_arguments
    log.debug(f" {name}={value if name not in sensitive else '*' * 8}")
Message: ' --webbrowser-headless=True'
Arguments: ()
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
BrokenPipeError: [Errno 32] Broken pipe

PR

$ streamlink -l debug | head -n1
[cli][debug] OS:         Linux-6.10.6-1-git-x86_64-with-glibc2.40

$ streamlink -l debug --stdout 2> >(head -n1)
[cli][debug] OS:         Linux-6.10.6-1-git-x86_64-with-glibc2.40

$ streamlink -l debug | head -n1
[cli][debug] OS:         Windows 10

@bastimeyer bastimeyer changed the title logger: suppress BrokenPipeError on flush Fix BrokenPipeError on stdout flush Aug 27, 2024
@bastimeyer bastimeyer force-pushed the logger/brokenpipeerror branch from 25651b9 to 3cfd29d Compare August 27, 2024 16:14
@bastimeyer bastimeyer changed the title Fix BrokenPipeError on stdout flush Fix OSError (BrokenPipeError) on stdout flush Aug 27, 2024
@bastimeyer bastimeyer merged commit 8d78991 into streamlink:master Aug 27, 2024
18 checks passed
@bastimeyer bastimeyer deleted the logger/brokenpipeerror branch August 27, 2024 16:21
@bastimeyer bastimeyer mentioned this pull request Sep 23, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
bug CLI logging
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
1 participant
@bastimeyer