OSError: [WinError 6] The handle is invalid

[Charlie-Bryant]

Python: 3.7.4 64bit Loguru: 0.5.3 OS: Windows 10

Hiya, My source code is quite large so I will not be able to show it here but I am running a series of tests using Pytest, the tests are utilizing classes that makes use of pythons multithreading capabilities. Each time I am calling logger.info (no matter which class) throughout the tests, this is an error that is printed into my results.

--- Logging error in Loguru Handler #0 --- Record was: {'elapsed': datetime.timedelta(seconds=1, microseconds=920783), 'exception': None, 'extra': {}, 'file': (name='init.py', path='U:\Python-Project\init.py'), 'function': 'initilise_test_enviroment', 'level': (name='INFO', no=20, icon='ℹ️'), 'line': 27, 'message': 'Initlilizing Test Enviroment', 'module': 'init', 'name': 'init', 'process': (id=7928, name='MainProcess'), 'thread': (id=7128, name='MainThread'), 'time': datetime(2021, 9, 6, 14, 58, 20, 993091, tzinfo=datetime.timezone(datetime.timedelta(seconds=3600), 'GMT Daylight Time'))} Traceback (most recent call last): File "C:\Users\BryantC\AppData\Local\Programs\Python\Python37\lib\site-packages\loguru_handler.py", line 177, in emit self._sink.write(str_record) File "C:\Users\BryantC \AppData\Local\Programs\Python\Python37\lib\site-packages\loguru_simple_sinks.py", line 26, in write self._stream.write(message) File "C:\Users\BryantC\AppData\Local\Programs\Python\Python37\lib\site-packages\colorama\ansitowin32.py", line 41, in write self.__convertor.write(text) File "C:\Users\BryantC\AppData\Local\Programs\Python\Python37\lib\site-packages\colorama\ansitowin32.py", line 162, in write self.write_and_convert(text) File "C:\Users\BryantC\AppData\Local\Programs\Python\Python37\lib\site-packages\colorama\ansitowin32.py", line 187, in write_and_convert self.write_plain_text(text, cursor, start) File "C:\Users\BryantCAppData\Local\Programs\Python\Python37\lib\site-packages\colorama\ansitowin32.py", line 196, in write_plain_text self.wrapped.flush() OSError: [WinError 6] The handle is invalid --- End of logging error

I know this will seem vague, but I am hoping that someone might know where to start with troubleshooting this?

[Delgan]

According to the traceback this seems related to Colorama. It looks like the stream handler (converting ansi code to terminal colors) is somehow closed while Loguru still needs to use it.

Can you please try to disable Pytest colorization as follow and see if your tests fail:

pytest --color=no

[Charlie-Bryant]

No change i'm afraid :(

[Delgan]

Ok, too bad. Unfortunately I have no idea where the issue may come from. It's weird that the traceback reports flush() as failing and not write() (see Colorama source code).

Now that I remember this is the exact same error as reported a few months ago: https://github.com/Delgan/loguru/issues/453

Do you use allure with your tests maybe?

Exact cause has not be found, but as a workaround you can disable Loguru colorization during your tests:

logger.remove()
logger.add(sys.stderr, colorize=False)

[Charlie-Bryant]

I have found another work around, I was previously launching pytest using pytest.main function as I need to run this during a script, however by running this through a sub process instead and inputting the command line parameters runs without any issues at all. At least there is a few work arounds :) Thanks for your help

[Delgan]

Ok, glad you figured out a workaround and thanks for sharing it. ;)

Too bad I can't investigate it. I'm thinking it can be related to this pytest issue but I can't be sure: https://github.com/pytest-dev/pytest/issues/8257

[nck974]

Hello, I have here an example to reproduce this issue: requirements.txt:

loguru==0.5.3
pygal==3.0.0
pygaljs==1.0.2
pylint==2.12.2
pytest==6.2.5
pytest-benchmark==3.4.1
pytest-html==3.1.1
selenium==4.1.0

test.py:

"""
Test loguru error
"""
from loguru import logger
import pytest

def main():
	"""
	Execute the tests
	"""
	pytest_args = []

	report_path='./report.html'

	pytest_args.append(f'--html={report_path}')
	pytest_args.append(f'--self-contained-html')
	pytest_args.append('./t/')

	_retcode = pytest.main(pytest_args)

	logger.info('Tests finished"')

if __name__ == '__main__':
	main()

conftest.py:

from loguru import logger
import pytest
from _pytest.logging import LogCaptureFixture

@pytest.fixture(autouse=True)
def caplog(caplog: LogCaptureFixture):
	"""
	Make pytest work with loguru. See:
	https://loguru.readthedocs.io/en/stable/resources/migration.html#making-things-work-with-pytest-and-caplog
	"""
	handler_id = logger.add(caplog.handler, format="{message}")
	yield caplog
	logger.remove(handler_id)


@pytest.fixture
def my_value():
	"""
	Some random value
	"""
	return 5

t/my_test.py

from loguru import logger


def test_loguru(my_value):
    """
    test
    """
    logger.info(f'Testing value {my_value}...')
    assert my_value <= 4, "Test value."

Output:

================================================================================================== test session starts ===================================================================================================
platform win32 -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: C:\Users\<MYUSER>\Desktop\delete_me
plugins: benchmark-3.4.1, html-3.1.1, metadata-1.11.0
collected 1 item

t\my_test.py F                                                                                                                                                                                                      [100%]

======================================================================================================== FAILURES ======================================================================================================== 
______________________________________________________________________________________________________ test_loguru _______________________________________________________________________________________________________ 

my_value = 5

    def test_loguru(my_value):
        """
        test
        """
        logger.info(f'Testing value {my_value}...')
>       assert my_value <= 4, "Test value."
E       AssertionError: Test value.
E       assert 5 <= 4

t\my_test.py:9: AssertionError
-------------------------------------------------------------------------------------------------- Captured stderr call -------------------------------------------------------------------------------------------------- 
--- Logging error in Loguru Handler #0 ---
Record was: {'elapsed': datetime.timedelta(microseconds=360851), 'exception': None, 'extra': {}, 'file': (name='my_test.py', path='C:\\Users\\<MYUSER>\\Desktop\\delete_me\\t\\my_test.py'), 'function': 'test_loguru', 'level': (name='INFO', no=20, icon='ℹ️'), 'line': 8, 'message': 'Testing value 5...', 'module': 'my_test', 'name': 'my_test', 'process': (id=248, name='MainProcess'), 'thread': (id=7108, name='MainThread'), 'time': datetime(2
022, 2, 1, 17, 49, 31, 454035, tzinfo=datetime.timezone(datetime.timedelta(seconds=3600), 'W. Europe Standard Time'))}
Traceback (most recent call last):
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\loguru\_handler.py", line 177, in emit
    self._sink.write(str_record)
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\loguru\_simple_sinks.py", line 26, in write
    self._stream.write(message)
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\colorama\ansitowin32.py", line 41, in write
    self.__convertor.write(text)
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\colorama\ansitowin32.py", line 162, in write
    self.write_and_convert(text)
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\colorama\ansitowin32.py", line 187, in write_and_convert
    self.write_plain_text(text, cursor, start)
  File "C:\Users\<MYUSER>\Desktop\delete_me\.venv\lib\site-packages\colorama\ansitowin32.py", line 196, in write_plain_text
    self.wrapped.flush()
OSError: [WinError 6] The handle is invalid
--- End of logging error ---
------------------------------------------------------------------------ generated html file: file://C:\Users\<MYUSER>\Desktop\delete_me\report.html ------------------------------------------------------------------------ 
================================================================================================ short test summary info ================================================================================================= 
FAILED t/my_test.py::test_loguru - AssertionError: Test value.
=================================================================================================== 1 failed in 0.13s ==================================================================================================== 
2022-02-01 17:49:31.4542022-02-01 17:49:31.570 | INFO     | __main__:main:23 - Tests finished"

[nck974]

None of the above fixes seem to fix the issue:

logger.remove()
logger.add(sys.stderr, colorize=False)

or

 pytest_args.append('--color=no')

The subprocess seems to be a workaround to get the job working, but you loose all the colorized output from loguru in windows so it is not a real solution:

def main():
	"""
	Execute the tests
	"""
	pytest_args = []

	report_path='./report.html'

	pytest_args.append(f'--html={report_path}')
	pytest_args.append(f'--self-contained-html')
	pytest_args.append('./t/')

	# _retcode = pytest.main(pytest_args)
	
	with Popen(['pytest',
			*pytest_args,
			str(__file__)], shell=True, stdout=PIPE, bufsize=1,
			universal_newlines=True) as p:
		for line in p.stdout:
			print(line, end='')
			pass
	logger.info('Tests finished')