Error with console output in Python 3.6 on Windows

[wheerd]

When running pytest in Python 3.6rc2 on Windows, there seems to be a problem with formatting the console output. The tests run fine until at some point it crashes because of a OSError: [WinError 87] The parameter is incorrect. This does not happen if I pipe the output into a file instead of having it in the console. I am not sure whether that is an issue with the py._io.TerminalWriter or something else. Since the 3.6 version is also not stable yet, so the issue might be there.

This is the trace back I am getting:

Traceback (most recent call last):
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 98, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 133, in _main
    config.hook.pytest_runtestloop(session=session)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 614, in execute
    res = hook_impl.function(*args)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 154, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 613, in execute
    return _wrapped_call(hook_impl.function(*args), self.execute)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 254, in _wrapped_call
    return call_outcome.get_result()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 279, in get_result
    raise ex[1].with_traceback(ex[2])
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 265, in __init__
    self.result = func()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 614, in execute
    res = hook_impl.function(*args)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\runner.py", line 66, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\runner.py", line 79, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "C:\Program Files\Python36\lib\site-packages\_pytest\runner.py", line 137, in call_and_report
    hook.pytest_runtest_logreport(report=report)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 614, in execute
    res = hook_impl.function(*args)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 207, in pytest_runtest_logreport
    self.write_fspath_result(rep.nodeid, letter)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 123, in write_fspath_result
    self._tw.write(res)
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 207, in write
    write_out(self._file, markupmsg)
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 342, in write_out
    fil.write(msg)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 40, in write
    self.__convertor.write(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 141, in write
    self.write_and_convert(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 169, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 175, in write_plain_text
    self.wrapped.flush()
OSError: [WinError 87] The parameter is incorrect

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 111, in wrap_session
    config.notify_exception(excinfo, config.option)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\config.py", line 923, in notify_exception
    excinfo=excinfo)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 614, in execute
    res = hook_impl.function(*args)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 164, in pytest_internalerror
    self.write_line("INTERNALERROR> " + line)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 145, in write_line
    self.ensure_newline()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 136, in ensure_newline
    self._tw.line()
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 212, in line
    self.write('\n')
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 207, in write
    write_out(self._file, markupmsg)
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 342, in write_out
    fil.write(msg)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 40, in write
    self.__convertor.write(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 141, in write
    self.write_and_convert(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 169, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 174, in write_plain_text
    self.wrapped.write(text[start:end])
OSError: [WinError 87] The parameter is incorrect

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\Python36\lib\runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "C:\Program Files\Python36\lib\runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "C:\Program Files\Python36\lib\site-packages\pytest.py", line 17, in <module>
    raise SystemExit(pytest.main())
  File "C:\Program Files\Python36\lib\site-packages\_pytest\config.py", line 57, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 614, in execute
    res = hook_impl.function(*args)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 127, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\main.py", line 122, in wrap_session
    exitstatus=session.exitstatus)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 745, in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 339, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 334, in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 613, in execute
    return _wrapped_call(hook_impl.function(*args), self.execute)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\vendored_packages\pluggy.py", line 250, in _wrapped_call
    wrap_controller.send(call_outcome)
  File "C:\Program Files\Python36\lib\site-packages\_pytest\terminal.py", line 359, in pytest_sessionfinish
    self._tw.line("")
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 212, in line
    self.write('\n')
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 207, in write
    write_out(self._file, markupmsg)
  File "C:\Program Files\Python36\lib\site-packages\py\_io\terminalwriter.py", line 342, in write_out
    fil.write(msg)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 40, in write
    self.__convertor.write(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 141, in write
    self.write_and_convert(text)
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 169, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "C:\Program Files\Python36\lib\site-packages\colorama\ansitowin32.py", line 174, in write_plain_text
    self.wrapped.write(text[start:end])
OSError: [WinError 87] The parameter is incorrect
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
OSError: [WinError 87] The parameter is incorrect

[qdamian]

+1. The same happens to me, with pytest 3.0.5, python 3.6.0 release (= RC 2) on Windows 8

[WiliTest]

same error in windows 7 with python36: when using read() or readlines() to read the content of a file.txt containing UTF8 characters

path=r"C:\Users\test.txt"
text= open(giomTXT_path, "r")
a= text.readlines()
print(a)
text.close()

a= text.readlines()
Python35: works with or without UTF8 (in the file read).
Python 36: works with ansi char but doesn't if the file read contain UTF8. I get this error:

OSError: [WinError 87] The parameter is incorrect
Exception ignored in: <_io.TextIOWrapper name='' mode='w' encoding='utf-
8'>
OSError: [WinError 87] The parameter is incorrect

a= text.read()
Python36: no error with ansi but UTF8 give that error:

OSError: [WinError 87] The parameter is incorrect
Exception ignored in: <_io.TextIOWrapper name='' mode='w' encoding='utf-
8'>
OSError: [WinError 87] The parameter is incorrect

[gboeing]

Same error on Windows 10 with Python 3.6.0.final.0 when trying to print to the console. This previously had worked fine in Python 3.5.

[RonnyPfannschmidt]

this looks like python 3.6 broke colorama - at first glace i believe tartley/colorama#121 needs to get merged and released

[RonnyPfannschmidt]

a potential workaround may be to uninstall colorama, can a windows user verify if that holds up?

[gboeing]

I just uninstalled colorama and tried to re-run my tests, but got the same error as before.

[wheerd]

My current workaround is piping the output into a file as that avoids the error.
Uninstalling colorama didn't work for me either.

[lsternlicht]

+1 with 3.6.0 & Windows Server 2016

[pkch]

Same error with 3.6.1 & Windows 10 Education build 14393. And just like @gboeing , when I uninstalled colorama, the error did not disappear.

[pkch]

Note that the error occurs even though pytest is not attempting to print any non-ASCII characters (in fact, the particular character on which this happens is a dot). Can anyone replicate this reliably without pytest?

[segevfiner]

I tried to debug this horror. It wasn't pretty... 😭

The error really originates from _io._WindowsConsoleIO.write (built-in/native method) and the real error is masked by some weird error handling code in that function (Modules/_io/winconsoleio.c:1002-1016). You instead get ERROR_INVALID_PARAMETER (87) from passing a 0 sized buffer to WideCharToMultiByte in that error handling code when WriteConsoleW fails.

The real error appears to be ERROR_INVALID_HANDLE from WriteConsoleW, this makes me suspicious that the real culprit isn't colorama but something else that causes the console handle opened by _io._WindowsConsoleIO to be randomly closed. So I placed a breakpoint on CloseHandle and lo and behold! CloseHandle does get called on that console handle by dup2 likely called by Pytest's FDCapture.

But why in the world would it only close it randomly?! Despite calling CloseHandle on it multiple times. Does that console handle have some weird randomized ref count or something... (Uninitialized memory? 😝). But handles don't really have ref counts... only the underlying objects do and it's actually the number of handles they have (or kernel references too but never mind that...).

Anyhow... What I think is the real issue here is that now Python is writing directly to an HANDLE and not to an msvcrt file descriptor and if the dup2 call somehow clobbers the underlying HANDLE that Python is using we get foobared.

Yet I still don't understand why it's random... 😕

Also note issue on colorama: tartley/colorama#119

[pkch]

I'm not sure where the code for dup2 is in CPython; I guess windows doesn't have it natively, so it's here perhaps https://github.com/python/cpython/blob/6f0eb93183519024cb360162bdd81b9faec97ba6/Python/dup2.c? If the native Windows fd duplication is used, it's probably this: https://msdn.microsoft.com/en-us/library/windows/desktop/ms724251(v=vs.85).aspx which does seem to use refcounts.

[segevfiner]

@pkch I think it's this posixmodule.c:7822-7835.

It might be calling the msvcrt/ucrt dup2 (Maybe with an underscore) you can see it's code in the ucrt sources in the Windows SDK. I might check later if it's really this one.