ValueError: I/O operation error on closed file

[afaderoTextNow]

Hello, I'm trying to debug an issue I'm seeing in my GHA CI job where I get this error
--- Logging error in Loguru Handler #1 --- Record was: {'elapsed': datetime.timedelta(seconds=728, microseconds=686962), 'exception': None, 'extra': {'req_params': {'secret': 'masked', 'client_type': '***', 'sync': 'sync'}, 'req_headers': {'Content-Type': 'application/json', 'scar': 'bypass_all', 'user-agent': 'Go-http-client/2.0'}, 'req_method': 'DELETE', 'req_path': '***/users/qe_cafivyevd8pchh', 'req_data': []}, 'file': (name='custom_logger.py', path='/home/runner/_work/***/custom_logger.py'), 'function': 'log_request', 'level': (name='DEBUG', no=10, icon='🐞'), 'line': 24, 'message': 'REQUEST', 'module': 'custom_logger', 'name': 'custom_logger', 'process': (id=420, name='MainProcess'), 'thread': (id=140513456748352, name='MainThread'), 'time': datetime(2024, 9, 6, 14, 47, 43, 884848, tzinfo=datetime.timezone(datetime.timedelta(0), 'UTC'))} Traceback (most recent call last): File "/home/runner/.local/share/virtualenvs/***-MgC1_4XS/lib/python3.11/site-packages/loguru/_handler.py", line 177, in emit self._sink.write(str_record) File "/home/runner/.local/share/virtualenvs/textnow-test-MgC1_4XS/lib/python3.11/site-packages/loguru/_simple_sinks.py", line 16, in write self._stream.write(message) ValueError: I/O operation on closed file. --- End of logging error ---

I'm using loguru to log http requests and responses from tests I run using pytest and I configure loguru as follows
custom_logger.py

from loguru import logger

log_debug_msg = "\n<level>{time} | {message} | {extra}</level>"
config = {
    "handlers": [
        {"sink": sys.stdout, "level": "DEBUG", "format": f"{log_debug_msg}"},
    ]
}
logger.configure(**config)


def log_request(req):
    req_logger = logger.bind(
        req_params=mask_secret(req=req.params),
        req_headers=mask_secret(req=req.headers),
        req_method=req.method,
        req_path=req.url,
        req_data=req.data,
    )
    req_logger.debug("REQUEST")


def log_response(resp):
    resp_logger = logger.bind(
        resp_code=resp.status_code,
        resp_req_body=resp.content,
        resp_req_url=mask_secret(resp=resp.request.url),
        resp_headers=resp.headers,
    )
    resp_logger.debug("RESPONSE")

The log_request() and log_response() are then called from my client.py file as follows:-

from custom_logger import log_request, log_response
...
req = Request(method, url, headers=headers, data=data, params=params)
    prepared_req = session.prepare_request(req)

    # log request
    log_request(req)

    resp = session.send(prepared_req, timeout=60, verify=False)

    # log response
    log_response(resp)

I can reproduce this error locally if I run a test locally from my IDE (pycharm) and then stop the test mid execution. If I run the test from the terminal and I just get a KeyboardInterrupt. What is puzzling to me is why this happening in CI. Just wondering if there's an issue with my configuration of loguru

[Delgan]

Hi @afaderoTextNow. Sorry for the late answer.

Nothing appears to be faulty with your logger configuration.

However, the exception ValueError: I/O operation on closed file. indicates that something called stream.close() on the sys.stdout sink, but that Loguru continued to use it afterwards.
Loguru will never closes the stream by itself. Therefore, the problem likely lies elsewhere.

Here is a example of such problem running pytest:

import sys
from loguru import logger


logger.remove()


def test_bench_1(capsys):
    # Here, "sys.stderr" is actually a mock object due to usage of "capsys" fixture.
    logger.add(sys.stderr, catch=False)
    logger.info("Test 1")


def test_bench_2():
    # After execution of the previous test, the mocked "sys.stderr" was closed by Pytest.
    # However, the handler was not removed from the Loguru logger. It'll raise a "ValueError" here.
    logger.info("Test 2", catch=False)

You should check that such pattern does not appear in your tests. Of course, the bug can likely be triggered in others subtle ways. You should make sure that the sinks used by Loguru are not closed prematurely.

I don't know more about Pycharm, but a similar problem must be at play. Because I know that Pycharm themselves replace sys.stdout and sys.stderr with their own stream objects. I'm not surprised that in some particular cases this can causes problems like the one you faced. However, this is an upstream problem and unfortunately I can't do much about it.

[afaderoTextNow]

Hi @Delgan, thanks for you reply. I'm inclined to agree with you that the issue is probably from somewhere else, probably the CI job being closed prematurely. I've taken it up with my SRE team and they're more likely to come up with a solution.