Strange test failure with pip 23.0.1

[frenzymadness]

I know it's not your problem at all but you might know enough to help me with the following strange problem causing test_output_env_subprocess_error[color] to fail.

I maintain python-build RPM package in Fedora and it now fails to build since we updated pip from 22.3.1 to 23.0.1. The problem is this failing test:

=================================== FAILURES ===================================
___________________ test_output_env_subprocess_error[color] ____________________

mocker = <pytest_mock.plugin.MockerFixture object at 0x7f76f42d7f10>
monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7f76f42bf5d0>
main_reload_styles = None
package_test_invalid_requirements = '/builddir/build/BUILD/build-0.10.0/tests/packages/test-invalid-requirements'
tmp_dir = '/tmp/python-build-test-0cztn5fn'
capsys = <_pytest.capture.CaptureFixture object at 0x7f76f43265d0>, color = True
stdout_body = ['\x1b[1m* Creating venv isolated environment...\x1b[0m', '\x1b[1m* Installing packages in isolated environment... (setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)\x1b[0m', '', '\x1b[2mTraceback (most recent call last):']
stdout_error = '\x1b[91mERROR\x1b[0m '

    @pytest.mark.pypy3323bug
    @pytest.mark.parametrize(
        ('color', 'stdout_error', 'stdout_body'),
        [
            (
                False,
                'ERROR ',
                [
                    '* Creating venv isolated environment...',
                    '* Installing packages in isolated environment... (setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)',
                    '',
                    'Traceback (most recent call last):',
                ],
            ),
            (
                True,
                '\33[91mERROR\33[0m ',
                [
                    '\33[1m* Creating venv isolated environment...\33[0m',
                    '\33[1m* Installing packages in isolated environment... '
                    '(setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)\33[0m',
                    '',
                    '\33[2mTraceback (most recent call last):',
                ],
            ),
        ],
        ids=['no-color', 'color'],
    )
    def test_output_env_subprocess_error(
        mocker,
        monkeypatch,
        main_reload_styles,
        package_test_invalid_requirements,
        tmp_dir,
        capsys,
        color,
        stdout_body,
        stdout_error,
    ):
        try:
            # do not inject hook to have clear output on capsys
            mocker.patch('colorama.init')
        except ModuleNotFoundError:  # colorama might not be available
            pass
    
        monkeypatch.delenv('NO_COLOR', raising=False)
        monkeypatch.setenv('FORCE_COLOR' if color else 'NO_COLOR', '')
    
        importlib.reload(build.__main__)  # reload module to set _STYLES
    
        with pytest.raises(SystemExit):
            build.__main__.main([package_test_invalid_requirements, '-o', tmp_dir])
        stdout, stderr = capsys.readouterr()
        stdout, stderr = stdout.splitlines(), stderr.splitlines()
    
        assert stdout[:4] == stdout_body
        assert stdout[-1].startswith(stdout_error)
    
>       assert len(stderr) == 1
E       assert 2 == 1
E        +  where 2 = len(["\x1b[31mERROR: Invalid requirement: 'this is invalid' (from line 1 of /tmp/build-reqs-ae11gsg7.txt)\x1b[0m\x1b[31m", '\x1b[0m'])

tests/test_main.py:371: AssertionError
=========================== short test summary info ============================
FAILED tests/test_main.py::test_output_env_subprocess_error[color] - assert 2...
===== 1 failed, 113 passed, 34 skipped, 12 deselected in 66.53s (0:01:06) ======

It seems that the captured output has 2 lines instead of one for some reason. I've tried to play around with COLUMNS env variable and it did not help.

The problem is that I'm not able to reproduce the problem outside of the Fedora build system (and mock).

The new version of pip vendors new versions of rich and colorama and my guess is that this problem might relate to that. See pypa/pip@22.3.1...23.0.1#diff-4054444a00305c03a81eff54cb76a5ec5d0001b8671420fa6760a172c8249f4d

Do you have an idea what might be causing this? I'm looking for an environment variable or some setting which stops the wrapping.

[uranusjr]

It’s most definitely related to the Rich upgrade; the second line actually contains only ANSI control codes and is visually empty. So I guess the test may need some fixup.

[frenzymadness]

One more thing is that when I remove the assert len(stderr) == 1, the test fails at the next line with:

=================================== FAILURES ===================================
___________________ test_output_env_subprocess_error[color] ____________________

mocker = <pytest_mock.plugin.MockerFixture object at 0x7fd44c68f450>
monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7fd44b7ef0d0>
main_reload_styles = None
package_test_invalid_requirements = '/builddir/build/BUILD/build-0.10.0/tests/packages/test-invalid-requirements'
tmp_dir = '/tmp/python-build-test-805_f6is'
capsys = <_pytest.capture.CaptureFixture object at 0x7fd44b79d750>, color = True
stdout_body = ['\x1b[1m* Creating venv isolated environment...\x1b[0m', '\x1b[1m* Installing packages in isolated environment... (setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)\x1b[0m', '', '\x1b[2mTraceback (most recent call last):']
stdout_error = '\x1b[91mERROR\x1b[0m '

    @pytest.mark.pypy3323bug
    @pytest.mark.parametrize(
        ('color', 'stdout_error', 'stdout_body'),
        [
            (
                False,
                'ERROR ',
                [
                    '* Creating venv isolated environment...',
                    '* Installing packages in isolated environment... (setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)',
                    '',
                    'Traceback (most recent call last):',
                ],
            ),
            (
                True,
                '\33[91mERROR\33[0m ',
                [
                    '\33[1m* Creating venv isolated environment...\33[0m',
                    '\33[1m* Installing packages in isolated environment... '
                    '(setuptools >= 42.0.0, this is invalid, wheel >= 0.36.0)\33[0m',
                    '',
                    '\33[2mTraceback (most recent call last):',
                ],
            ),
        ],
        ids=['no-color', 'color'],
    )
    def test_output_env_subprocess_error(
        mocker,
        monkeypatch,
        main_reload_styles,
        package_test_invalid_requirements,
        tmp_dir,
        capsys,
        color,
        stdout_body,
        stdout_error,
    ):
        try:
            # do not inject hook to have clear output on capsys
            mocker.patch('colorama.init')
        except ModuleNotFoundError:  # colorama might not be available
            pass
    
        monkeypatch.delenv('NO_COLOR', raising=False)
        monkeypatch.setenv('FORCE_COLOR' if color else 'NO_COLOR', '')
    
        importlib.reload(build.__main__)  # reload module to set _STYLES
    
        with pytest.raises(SystemExit):
            build.__main__.main([package_test_invalid_requirements, '-o', tmp_dir])
        stdout, stderr = capsys.readouterr()
        stdout, stderr = stdout.splitlines(), stderr.splitlines()
    
        assert stdout[:4] == stdout_body
        assert stdout[-1].startswith(stdout_error)
    
>       assert stderr[0].startswith('ERROR: Invalid requirement: ')
E       assert False
E        +  where False = <built-in method startswith of str object at 0x7fd44b687af0>('ERROR: Invalid requirement: ')
E        +    where <built-in method startswith of str object at 0x7fd44b687af0> = "\x1b[31mERROR: Invalid requirement: 'this is invalid' (from line 2 of /tmp/build-reqs-deon863i.txt)\x1b[0m\x1b[31m".startswith

tests/test_main.py:371: AssertionError
=========================== short test summary info ============================
FAILED tests/test_main.py::test_output_env_subprocess_error[color] - assert F...
========== 1 failed, 113 passed, 34 skipped, 12 deselected in 56.78s ===========

It seems that the new rich adds color info for that so the last assert fails as well.

[henryiii]

It's the vendored version of pip (the one setup by the virtualenv process) that matters, I expect, since I think we test with a host pip 23. Looks like the problem is that stderr is now colored too.