logging.StreamHandler produces BrokenPipeError when cut short by head utility

[blhsing]

Bug report

Bug description:

The following code:

# test.py
import sys
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(logging.StreamHandler(sys.stdout))
logger.debug('foo')
logger.debug('bar')

when piped to head -n1, produces:

# python test.py | head -n1
foo
--- Logging error ---
Traceback (most recent call last):
  File "/src/cpython/Lib/logging/__init__.py", line 1155, in emit
    self.flush()
    ~~~~~~~~~~^^
  File "/src/cpython/Lib/logging/__init__.py", line 1137, in flush
    self.stream.flush()
    ~~~~~~~~~~~~~~~~~^^
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "test.py", line 8, in <module>
    logger.debug('bar')
Message: 'bar'
Arguments: ()
Exception ignored while flushing sys.stdout:
BrokenPipeError: [Errno 32] Broken pipe

This is because logging.StreamHandler.emit does not handle BrokenPipeError when flushing the stream.
I will fix this with the approach recommended by Note on SIGPIPE.

CPython versions tested on:

CPython main branch, 3.13

Operating systems tested on:

Linux

Linked PRs

• gh-134568: added handler for BrokenPipeError to logging.StreamHandler.emit #134569

[vsajip]

I'm not sure the approach suggested in the SIGPIPE note applies here:

• It may not be caused only by piping to head, tail or similar.
• A permanent dup of sys.stdout to os.devnull might be surprising in itself if the process is not about to exit anyway.
• StreamHandler is used for other streams and it's not clear how duping sys.stdout to os.devnull is appropriate.

I suggest opening a discussion on discuss.python.org to see what others (including other core developers) think about the BrokenPipeError issue.

[ZeroIntensity]

A permanent dup of sys.stdout to os.devnull might be surprising in itself if the process is not about to exit anyway.
StreamHandler is used for other streams and it's not clear how duping sys.stdout to os.devnull is appropriate.

I just want to reiterate these two points. The linked PR is too specific to a certain use-case.

[vsajip]

Note that this error is not produced by logging.StreamHandler and not really connected to logging, but rather in low-level C code:

cpython/Python/pylifecycle.c

Lines 1803 to 1835 in 3c05251

	static int
	flush_std_files(void)
	{
	PyObject *file;
	int status = 0;
	if (_PySys_GetOptionalAttr(&_Py_ID(stdout), &file) < 0) {
	status = -1;
	}
	else if (file != NULL && file != Py_None && !file_is_closed(file)) {
	if (_PyFile_Flush(file) < 0) {
	status = -1;
	}
	}
	if (status < 0) {
	PyErr_FormatUnraisable("Exception ignored while flushing sys.stdout");
	}
	Py_XDECREF(file);
	if (_PySys_GetOptionalAttr(&_Py_ID(stderr), &file) < 0) {
	PyErr_Clear();
	status = -1;
	}
	else if (file != NULL && file != Py_None && !file_is_closed(file)) {
	if (_PyFile_Flush(file) < 0) {
	PyErr_Clear();
	status = -1;
	}
	}
	Py_XDECREF(file);
	return status;
	}

The following script, which contains no calls to logging:

# test2.py
import sys
print('foo')
sys.stdout.flush()
print('bar')
sys.stdout.flush()

results in this:

$ python3 test2.py | head -1
foo
Traceback (most recent call last):
  File "/disk2/vinay/projects/scratch/logging/134568/test2.py", line 5, in <module>
    sys.stdout.flush()
    ~~~~~~~~~~~~~~~~^^
BrokenPipeError: [Errno 32] Broken pipe
Exception ignored on flushing sys.stdout:
BrokenPipeError: [Errno 32] Broken pipe

And quite frankly, any code in an application might flush sys.stdout which would lead to this happening. So you can leave this as an issue, but disconnect it from logging and mention it as related to the C code referenced above. I'll mark this issue as pending (I'll close it if you, @blhsing, don't restate it as a sys.stdout.flush() problem rather than logging-related). I'll close the PR as it seems not well thought out and will not fix the behavior referred to here.

[vsajip]

@serhiy-storchaka As per my comments above, I'm not sure this is particularly a logging issue - any code which flushes sys.stdout can lead to a BrokenPipeError. That's why I removed it from the Logging Issues. What's your thinking on it?