bug: Test suite fails on Windows

[dalito]

Description of the bug

Running the test suite fails on Windows 10 or 11 (German locale). The failure is only obvious when running pytest directly.
It does not matter if it is run in powershell, cmd or cmder. The crash always happens in the test test_capture_function_and_subprocess_output object address.

The same test fails when the test are run in bash shell from git for windows. However, it fails with an assertion error.

C:\Users\david\MyProg\gh-dalito\failprint (main -> origin)
(failprint) λ duty test
> Running tests
C:\Users\david\MyProg\gh-dalito\failprint (main -> origin)
(failprint) λ echo %errorlevel%
0
C:\Users\david\MyProg\gh-dalito\failprint (main -> origin)
(failprint) λ py -m pytest -v
================================================= test session starts =================================================
platform win32 -- Python 3.12.7, pytest-8.3.4, pluggy-1.5.0 -- C:\Users\david\MyProg\gh-dalito\failprint\.venv\Scripts\python.exe
cachedir: .pytest_cache
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase(WindowsPath('C:/Users/david/MyProg/gh-dalito/failprint/.hypothesis/examples'))
Using --randomly-seed=2862494129
rootdir: C:\Users\david\MyProg\gh-dalito\failprint
configfile: pyproject.toml
plugins: hypothesis-6.123.1, cov-6.0.0, randomly-3.16.0, timeout-2.3.1, xdist-3.6.1
collected 78 items

tests/test_runners.py::test_process_capture_none PASSED                                                          [  1%]
tests/test_runners.py::test_return_failure_code PASSED                                                           [  2%]
tests/test_runners.py::test_fails_with_falsy_object PASSED                                                       [  3%]
tests/test_runners.py::test_capture_function_and_subprocess_output object address  : 0000018201AF4C10
object refcount : 5
object type     : 00007FFC9A44E2B0
object type name: OSError
object repr     : OSError(9, 'Das Handle ist ung├╝ltig', None, 6, None)
lost sys.stderr

C:\Users\david\MyProg\gh-dalito\failprint (main -> origin)
(failprint) λ failprint --version
failprint 1.0.4.dev2+g807a234

To Reproduce

The assertion error from the bash shell (probably unrelated):

david@acompc-ws MINGW64 ~/MyProg/gh-dalito/failprint (main)
$ py -m pytest -v
============================= test session starts =============================
platform win32 -- Python 3.12.7, pytest-8.3.4, pluggy-1.5.0 -- C:\Users\david\MyProg\gh-dalito\failprint\.venv\Scripts\python.exe
cachedir: .pytest_cache
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase(WindowsPath('C:/Users/david/MyProg/gh-dalito/failprint/.hypothesis/examples'))
Using --randomly-seed=3183279503
rootdir: C:\Users\david\MyProg\gh-dalito\failprint
configfile: pyproject.toml
plugins: hypothesis-6.123.1, cov-6.0.0, randomly-3.16.0, timeout-2.3.1, xdist-3.6.1
collecting ... collected 78 items

tests/test_formats.py::test_printable_command_with_callable[printable_command-args8-kwargs8-printable_command(Repr(value=0), repr=Repr(value='marvin'))] PASSED [  1%]
(...)
tests/test_runners.py::test_capture_function_and_subprocess_output FAILED [ 64%]
(...)
tests/test_lazy.py::test_decorating_function PASSED                      [100%]

================================== FAILURES ===================================
_________________ test_capture_function_and_subprocess_output _________________

capsys = <_pytest.capture.CaptureFixture object at 0x000002A155EE1C70>

    def test_capture_function_and_subprocess_output(capsys: pytest.CaptureFixture) -> None:
        """Assert we capture everything when running a function.

        Arguments:
            capsys: Pytest fixture to capture output.
        """

        def function() -> None:
            print("print")
            sys.stdout.write("sys stdout write\n")
            os.system("echo os system")  # noqa: S605,S607
            subprocess.run(["sh", "-c", "echo sh -c echo"], check=False)  # noqa: S603,S607

        with capsys.disabled(), Capture.BOTH.here() as captured:
            function()

        lines = str(captured).rstrip("\n").split("\n")
>       assert lines == ["print", "sys stdout write", "os system", "sh -c echo"]
E       AssertionError: assert ['os system',...stdout write'] == ['print', 'sy... 'sh -c echo']
E
E         At index 0 diff: 'os system' != 'print'
E
E         Full diff:
E           [
E         +     'os system',
E         +     'sh -c echo',...
E
E         ...Full output truncated (5 lines hidden), use '-vv' to show

tests\test_runners.py:369: AssertionError
=========================== short test summary info ===========================
FAILED tests/test_runners.py::test_capture_function_and_subprocess_output - A...
================== 1 failed, 72 passed, 5 skipped in 12.95s ===================

Additional context

Environment information

$ failprint --debug-info
- __System__: Windows-10-10.0.19045-SP0
- __Python__: cpython 3.12.7 (C:\Users\david\MyProg\gh-dalito\failprint\.venv\Scripts\python.exe)
- __Environment variables__:
- __Installed packages__:
  - `failprint` v1.0.4.dev2+g807a234

[pawamoy]

Hi @dalito, thanks for the report.

I'm aware of the issue, but wasn't able to reproduce it in CI (GitHub's Windows runners). I'm not willing to spend more time debugging Windows issues.

The possible solutions are:

• Using WSL2.
• Setting the following environment variable: PYTHONLEGACYWINDOWSSTDIO=1, and optionally PYTHONUTF8=1 or PYTHONIOENCODING=UTF8.

Let me know what you think 🙂

[dalito]

I think that it would be good to require less fiddling with environment variables because they affect programs run with duty. For example pytest works fine on Windows without setting any environment variable. But if these environment variables are set for duty/failprint, pytest does no longer print correct unicode to the console.

But I very well understand

I'm not willing to spend more time debugging Windows issues.

especially after reading pawamoy/duty#23 of @blairconrad. So I spent a little time. 😃

From my analysis there are three problems:

• The error that I reported above is due to os.dup2 and file descriptor behaving differently on windows which is a result of implementing https://peps.python.org/pep-0528/ in Python 3.6. Setting PYTHONLEGACYWINDOWSSTDIO=1 brings back the old state before this change.
  • _io._WindowsConsoleIO breaks in the face of fd redirection python/cpython#74740
  • https://stackoverflow.com/questions/52373180/python-on-windows-handle-invalid-when-redirecting-stdout-writing-to-file
• Setting PYTHONUTF8=1 and PYTHONIOENCODING=UTF8 is only required because of false utf8-assumptions which are not correct for every Windows. I think that this can be fixed. Some background info is discussed here. I'll submit a PR
• Reproducing the failures on gh-actions is difficult because all windows runner use utf8 as encoding in PowerShell whereas European windows has cp850. This hides errors. I could not find a way to change the PowerShell to behave exactly as locally. But by modifing PowerShell´s $outputencoding at least some encoding errors can be reproduced: https://github.com/dalito/failprint/actions/runs/12527889697/job/34941913807 (from PR1 in my fork)

...looking forward to switching to utf8 on Windows by default in Python 3.15.

[dalito]

Here is a demo how Capture is affected by PYTHONLEGACYWINDOWSSTDIO setting:

import os
import subprocess
import sys

from failprint.capture import Capture, CaptureManager

    
def print_things() -> None:
    print("1ö")
    sys.stderr.write("2ä\n")
    os.system("echo 3ß")
    if sys.platform == "win32":
        subprocess.run(["cmd.exe", "/c", "echo 4ü >&2"], shell=True)
    else:
        subprocess.run(["sh", "-c", "echo 4ü >&2"], shell=True)
        

print("Capturing with Capture.NONE")
with Capture.NONE.here() as captured:
    print_things()

if captured._output is not None:
    print(f"{captured}")

print("\n...done with Capture.NONE!")
captured = None

with CaptureManager(Capture.BOTH) as captured:
    print_things()

print(f"\nCapturing with Capture.BOTH:\n{captured}")
print(f"Done!")

Log from powershell 7.4.x on Windows 10 (codepage 850):

(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> $Env:PYTHONLEGACYWINDOWSSTDIO
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> py .\capture_problem.py
Capturing with Capture.NONE
1ö
2ä
3ß
4ü

...done with Capture.NONE!
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> $Env:PYTHONLEGACYWINDOWSSTDIO=1
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> $Env:PYTHONLEGACYWINDOWSSTDIO
1
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> py .\capture_problem.py
Capturing with Capture.NONE
1÷
2õ
3ß
4ü

...done with Capture.NONE!
Traceback (most recent call last):
  File "C:\Users\david\MyProg\gh-dalito\failprint\capture_problem.py", line 28, in <module>
    with CaptureManager(Capture.BOTH) as captured:
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\david\MyProg\gh-dalito\failprint\src\failprint\capture.py", line 185, in __exit__
    self._output = self._temp_file.read()
                   ^^^^^^^^^^^^^^^^^^^^^^
  File "C:\dev\Python312\Lib\tempfile.py", line 499, in func_wrapper
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "<frozen codecs>", line 322, in decode
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xf6 in position 1: invalid start byte

(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> $Env:PYTHONIOENCODING="cp850"
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint> py capture_problem.py
Capturing with Capture.NONE
1ö
2ä
3ß
4ü

...done with Capture.NONE!
Traceback (most recent call last):
  File "C:\Users\david\MyProg\gh-dalito\failprint\capture_problem.py", line 28, in <module>
    with CaptureManager(Capture.BOTH) as captured:
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\david\MyProg\gh-dalito\failprint\src\failprint\capture.py", line 185, in __exit__
    self._output = self._temp_file.read()
                   ^^^^^^^^^^^^^^^^^^^^^^
  File "C:\dev\Python312\Lib\tempfile.py", line 499, in func_wrapper
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "<frozen codecs>", line 322, in decode
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x94 in position 1: invalid start byte
(failprint) PS C:\Users\david\MyProg\gh-dalito\failprint>

Setting PYTHONLEGACYWINDOWSSTDIO leads to incorrect unicode with Capture.NONE in addition to the error. The encoding must be set to cp850 (for my windows as indicated by os.device_encoding(0)), not utf8.
For a moment I thought to have a solution but apparently I haven't. pytestshows that it is in principle possible but it seems so hard to get there.

[dalito]

This is without any environment variable set.

Attaching a debugger to my script above shows that print("1ö") raises an OSError that is swallowed by calling sys.stdout.flush() / sys.stderr.flush() in Capture.CaptureManager.__exit__(...). Avoiding the flush on the invalid sys.stdout handle, surfaces the same error as seen in the debugger:

(failprint) λ py capture_problem.py
Capturing with Capture.NONE
1ö
2ä
3ß
4ü

...done with Capture.NONE!
1ö
Traceback (most recent call last):
  File "C:\Users\david\MyProg\gh-dalito\failprint\capture_problem.py", line 29, in <module>
    print_things()
  File "C:\Users\david\MyProg\gh-dalito\failprint\capture_problem.py", line 9, in print_things
    print("1ö")
OSError: [WinError 6] Das Handle ist ungültig

The file descriptor is 1 (determined by sys.stdout.fileno()) just before print("1ö"). I was expecting a different fileno than 1 but I may be on the wrong track.

[pawamoy]

Thank you for doing this hard investigation work @dalito. I suppose we could look into how Pytest handles capturing output at the file descriptor level (it has a fixture for that indeed).

[dalito]

I tried a bit more with some success. The code is in the branch https://github.com/dalito/failprint/tree/windows-encoding-fix

With this branch the tests pass locally on Win10/Win11. The GitHub runner shows some strange behavior but passes the tests here https://github.com/dalito/failprint/actions/runs/12572960190 - The strange behavior is that os.device_encoding(1) is None on the GitHub runner. It is cp850 for me locally. Another reason why reproducing encoding errors is difficult in CI.

With the demo script above, the first two captured lines give utf8 the next two cp850 encoded output (on German Windows 10/11). Therefore, I capture binary streams and try to decode the mess afterwards (which is hacky).

The os.dup2 use which leads to a closed file handle (and the OSError in the bug report) is addressed by recreating stdout like pytest does in https://github.com/pytest-dev/pytest/blob/e8c2082d751999fa0ebf1ba335cfec3b022f0a88/src/_pytest/capture.py#L83

What I did is too hacky and too sensitive to minor differences to be used here. Now, after finding out more, I don't believe there is a good general solution for windows at the moment.

I will stop my work on this. At least I learned quite a bit.

[pawamoy]

OK, thanks for all your efforts. This will be invaluable if someone wants to pick it up from there 🙂

What I can offer is that we switch back to the old way of capturing output for Python callables, for Windows only: patching sys.stdout/stderr/stdin (instead of using file descriptors). This way at least capture will work even on Windows, even if in a limited way (it won't be able to capture output from subprocesses the callable spawns). WDYT?

I initially didn't want to do that but seeing all the efforts you've made with @blairconrad, I think it's only fair 😄

[dalito]

What I can offer is that we switch back to the old way of capturing output for Python callables, for Windows only: patching sys.stdout/stderr/stdin (instead of using file descriptors).

Yes this way was also suggested by the C-Python devs. Let me know when I should try something out.

[blairconrad]

Thanks for thinking of me, @pawamoy.

For me, it looks like patching sys.std{out,err,in} would be an improvement for Windows users. Heck, with that behaviour, you and I probably never would have had to interact at all (which would be a loss, since I've had a good time, but also technically a success from the project's point of view).

If you're particularly worried about negative effects, the behaviour could default to patching, with a command-line or environment variable override. But that feels like a lot of work for maybe no reason; I'd probably just start patching and wait for the fallout.
(Assuming, of course, you feel it's worthwhile putting any support for Window in.)

And, like @dalito (nice work, BTW), I'm also available to test, code, review docs, whatever.

[pawamoy]

Great, I opened #23. Closing this in favor of it 🙂

[pawamoy]

Off-topic, but kinda relevant 🤣 https://blog.orange.tw/posts/2025-01-worstfit-unveiling-hidden-transformers-in-windows-ansi/