Pip: Log debug and informational messages to stderr only

[chrahunt]

What's the problem this feature will solve?

Commands that generate output for the user (pip list, pip freeze) must be concerned with debug output.

Describe the solution you'd like

As mentioned in #6099:

1. all log messages should go to stderr instead of stdout
2. command API related output should use a dedicated interface that outputs to stdout

Any issue that seeks to make the CLI more usable would benefit from this change. This also avoids issues like #6024.

Alternative Solutions

Originally, ad-hoc redirection of logger output to stderr was used to preserve command output. This could be used again, but it would make logging output from commands inconsistent in pip.

Additional Context

• #6099

[cjerdonek]

I was planning to do this between the 19.2 and 19.3 release but would be okay with someone else doing it. (I had already done it for subprocess logging in PR #6339.)

I was thinking this should be implemented in three PR's as follows:

1. Switch all command API output to use a function called something like write_output() whose initial implementation just delegates to logging.INFO (so this would be a refactoring PR with no behavior change). This PR will let us review where all the API output is happening.

2. Change the implementation of write_output() from using a logging call to writing directly to stdout.

3. Change the logging configuration to use stderr streams for everything instead of stdout for some. This step will involve simplifying our logging config and in particular merging the subprocess logger introduced in PR #6339 with the main logger, as they would now both be using the same stderr stream.

[pradyunsg]

One of the things we lose with the proposed changes is the timestamping functionality that we added to --log files.

[cjerdonek]

One of the things we lose with the proposed changes is the timestamping functionality that we added to --log files.

We can address this by having the proposed write_output() also log to the log file the things that would be going to stdout. (The log file is already more verbose than the normal log level, IIRC.)

[adamRogerson]

1. Switch all command API output to use a function called something like `write_output()` whose initial implementation just delegates to `logging.INFO` (so this would be a refactoring PR with no behavior change). This PR will let us review where all the API output is happening.

I have started working on this but am unsure how long it will take.
https://github.com/adamRogerson/pip/tree/6758_api_output

[pradyunsg]

We can address this by having the proposed write_output() also log to the log file the things that would be going to stdout. (The log file is already more verbose than the normal log level, IIRC.)

At that point, we're starting to re-implement functionality from the logging module. :(

[cjerdonek]

What I was suggesting would mean adding a call to a specific logger. So it wouldn’t be reimplementing any logging logic but rather calling it. The benefit of having a write_output function is that it centralizes the logic of what we want to do with command output, since it is distinguished from non-command output and would be going through one code path.

[adamRogerson]

What I was suggesting would mean adding a call to a specific logger. So it wouldn’t be reimplementing any logging logic but rather calling it. The benefit of having a write_output function is that it centralizes the logic of what we want to do with command output, since it is distinguished from non-command output and would be going through one code path.

I am happy to follow on from #6876 with this. Am i correct in thinking we should have a have a specific logger for stdout messages that is then used inside write_output ?

[cjerdonek]

Yes and no. In my original proposal, we would only write to stdout using sys.stdout inside write_output. But @pradyunsg suggested that we might want to include the stdout output in the log file as well. If we do that, we’d want to create / configure a new logger for that purpose (a bit like what I did with the subprocess logger) and make a call to that — in addition to writing to stdout. Depending on how much you know about logging config, you might need some help if you were to try the PR.

[adamRogerson]

@cjerdonek That makes it clear to me now. Ill see how far copying the subprocess_logger gets me. One question i have is why we would use sys.stdout() over print()

[cjerdonek]

print is probably fine, too. We can always change it if we need to. Also, you don’t necessarily want to copy the subprocess logger. It’s just an example of a different logger being used.

[deveshks]

Hi @chrahunt , @cjerdonek and @pradyunsg ,

I saw that there was a PR for this issue made https://github.com/pypa/pip/pull/6975 where the review comments were not followed up. Is it possible that I make a new PR based on the code from that PR and addressing the PR comments?

[uranusjr]

@deveshks Go ahead! You can start by fetching the pull request locally to save some work.

[deveshks]

So I was able to apply points 2 and 3 in the PR, and after that, the command mentioned in https://github.com/pypa/pip/issues/6024#issue-382867081 was giving the correct output

$ pip --verbose freeze 2> '/dev/null' | grep -v -e '^-e'  | LC_COLLATE='C' sort
appdirs==1.4.3
attrs==19.3.0
distlib==0.3.0
filelock==3.0.12
more-itertools==8.2.0
packaging==20.3
pluggy==0.13.1
py==1.8.1
pyparsing==2.4.7
pytest==5.4.1
six==1.14.0
toml==0.10.0
tox==3.14.6
virtualenv==20.0.18
wcwidth==0.1.9

But now I see that a lot of tests are failing after this change. How would I go about fixing them? One thing I was trying was to change around the usage of result.stdout and result.stderr in asserts, and that causes some of the tests to pass.

Are there any other approaches to fix the remaining tests, especially https://github.com/pypa/pip/blob/master/tests/functional/test_broken_stdout.py ?

[deveshks]

Hi @uranusjr

Any tips on how to proceed with fixing the tests after adding the required code as per the above comment, especially https://github.com/pypa/pip/blob/master/tests/functional/test_broken_stdout.py would be helpful.

[cjerdonek]

So I was able to apply points 2 and 3 in the PR

When you say points 2 and 3, are you referring to the 3 steps I outlined in this comment?
https://github.com/pypa/pip/issues/6758#issuecomment-514470982

If so, I was saying those should be done in separate PR's rather than one PR. It will be easier that way. Where is your PR? I don't see it linked to this issue. Is it just local to you or did you post it?

[deveshks]

So I was able to apply points 2 and 3 in the PR

When you say points 2 and 3, are you referring to the 3 steps I outlined in this comment?
#6758 (comment)

Yes, I was referring to that comment.

If so, I was saying those should be done in separate PR's rather than one PR. It will be easier that way. Where is your PR? I don't see it linked to this issue. Is it just local to you or did you post it?

I didn't create a PR for it, but I have the relevant commit for the changes in my fork at https://github.com/deveshks/pip/commit/7fcaf271463ee5f494d603f635f7da19b567d877 . This commit also addresses some follow-up comments made at https://github.com/pypa/pip/pull/6975

I think this commit should cover 2 (adding print(msg % args) to write_output) and 3 (changing "stream": log_streams["stdout"] to "stream": log_streams["stderr"],, but I there might still be things missing and more changes needed here.

[cjerdonek]

I think this commit should cover 2 (adding print(msg % args) to write_output) and 3 (changing "stream": log_streams["stdout"] to "stream": log_streams["stderr"],, but I there might still be things missing and more changes needed here.

This is why I was saying it should be done in separate PR's. It will be easier to implement, review, and discuss that way.

[deveshks]

I think this commit should cover 2 (adding print(msg % args) to write_output) and 3 (changing "stream": log_streams["stdout"] to "stream": log_streams["stderr"],, but I there might still be things missing and more changes needed here.

This is why I was saying it should be done in separate PR's. It will be easier to implement, review, and discuss that way.

Makes sense, and in order to proceed with 2 (Change the implementation of write_output() from using a logging call to writing directly to stdout.) , is it enough to extend the work done in https://github.com/pypa/pip/pull/6975 after addressing review comments to begin with, and then we can talk further if any more changes are needed for finishing 2.

After that I can tackle 3 in a separate PR.

[cjerdonek]

Yes, I believe so. Thanks!

[deveshks]

Yes, I believe so. Thanks!

I applied the changes but I found that the tests in https://github.com/pypa/pip/blob/master/tests/functional/test_broken_stdout.py are now failing. Any suggestions on how to get that fixed would be really helpful.

I didn't want to file a PR which doesn't pass tests, so wanted clarifications on fixing them before filing one, sorry about that.

The current changes are at https://github.com/pypa/pip/compare/master...deveshks:add_command_output_logger and the test failures being observed are as follows.

Broken test_broken_stdout

tests/functional/test_broken_stdout.py FFF                                                                 [100%]

==================================================== FAILURES ====================================================
____________________________________________ test_broken_stdout_pipe _____________________________________________

deprecated_python = False

    def test_broken_stdout_pipe(deprecated_python):
        """
        Test a broken pipe to stdout.
        """
>       stderr, returncode = setup_broken_stdout_test(
            ['pip', 'list'], deprecated_python=deprecated_python,
        )

tests/functional/test_broken_stdout.py:35: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = ['pip', 'list'], deprecated_python = False

    def setup_broken_stdout_test(args, deprecated_python):
        proc = subprocess.Popen(
            args, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
        )
        # Call close() on stdout to cause a broken pipe.
        proc.stdout.close()
        returncode = proc.wait()
        stderr = proc.stderr.read().decode('utf-8')

        expected_msg = 'ERROR: Pipe to stdout was broken'
        if deprecated_python:
            assert expected_msg in stderr
        else:
>           assert stderr.startswith(expected_msg)
E           assert False
E            +  where False = <built-in method startswith of str object at 0x10c4ceea0>('ERROR: Pipe to stdout was broken')
E            +    where <built-in method startswith of str object at 0x10c4ceea0> = "Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>\nBrokenPipeError: [Errno 32] Broken pipe\n".startswith

tests/functional/test_broken_stdout.py:26: AssertionError
______________________________________ test_broken_stdout_pipe__log_option _______________________________________

deprecated_python = False
tmpdir = Path('/private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pytest-of-devesh/pytest-30/test_broken_stdout_pipe__log_o0')

    def test_broken_stdout_pipe__log_option(deprecated_python, tmpdir):
        """
        Test a broken pipe to stdout when --log is passed.
        """
        log_path = os.path.join(str(tmpdir), 'log.txt')
>       stderr, returncode = setup_broken_stdout_test(
            ['pip', '--log', log_path, 'list'],
            deprecated_python=deprecated_python,
        )

tests/functional/test_broken_stdout.py:51: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = ['pip', '--log', '/private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pytest-of-devesh/pytest-30/test_broken_stdout_pipe__log_o0/log.txt', 'list']
deprecated_python = False

    def setup_broken_stdout_test(args, deprecated_python):
        proc = subprocess.Popen(
            args, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
        )
        # Call close() on stdout to cause a broken pipe.
        proc.stdout.close()
        returncode = proc.wait()
        stderr = proc.stderr.read().decode('utf-8')

        expected_msg = 'ERROR: Pipe to stdout was broken'
        if deprecated_python:
            assert expected_msg in stderr
        else:
>           assert stderr.startswith(expected_msg)
E           assert False
E            +  where False = <built-in method startswith of str object at 0x10c4b50e0>('ERROR: Pipe to stdout was broken')
E            +    where <built-in method startswith of str object at 0x10c4b50e0> = "Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>\nBrokenPipeError: [Errno 32] Broken pipe\n".startswith

tests/functional/test_broken_stdout.py:26: AssertionError
________________________________________ test_broken_stdout_pipe__verbose ________________________________________

deprecated_python = False

    def test_broken_stdout_pipe__verbose(deprecated_python):
        """
        Test a broken pipe to stdout with verbose logging enabled.
        """
>       stderr, returncode = setup_broken_stdout_test(
            ['pip', '-v', 'list'], deprecated_python=deprecated_python,
        )

tests/functional/test_broken_stdout.py:67: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = ['pip', '-v', 'list'], deprecated_python = False

    def setup_broken_stdout_test(args, deprecated_python):
        proc = subprocess.Popen(
            args, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
        )
        # Call close() on stdout to cause a broken pipe.
        proc.stdout.close()
        returncode = proc.wait()
        stderr = proc.stderr.read().decode('utf-8')

        expected_msg = 'ERROR: Pipe to stdout was broken'
        if deprecated_python:
            assert expected_msg in stderr
        else:
>           assert stderr.startswith(expected_msg)
E           assert False
E            +  where False = <built-in method startswith of str object at 0x10c4b5030>('ERROR: Pipe to stdout was broken')
E            +    where <built-in method startswith of str object at 0x10c4b5030> = "Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>\nBrokenPipeError: [Errno 32] Broken pipe\n".startswith

tests/functional/test_broken_stdout.py:26: AssertionError
============================================ short test summary info =============================================
FAIL tests/functional/test_broken_stdout.py::test_broken_stdout_pipe
FAIL tests/functional/test_broken_stdout.py::test_broken_stdout_pipe__log_option
FAIL tests/functional/test_broken_stdout.py::test_broken_stdout_pipe__verbose
============================================ 3 failed in 1.81 seconds ============================================
ERROR: InvocationError for command /Users/devesh/pip/.tox/py/bin/pytest --timeout 300 tests/functional/test_broken_stdout.py (exited with code 1)
____________________________________________________ summary _____________________________________________________
ERROR:   py: commands failed

[cjerdonek]

I'll take a look at some point. (I wrote those tests so should be able to help you.) By the way, I think it's better to file PR's even if the tests aren't passing. You can mark them WIP (work in progress) or use GitHub's "Draft" indicator. Otherwise, it's harder to review and give feedback on code. Like, right now you're having to clutter the issue comments with information about your code, but that wouldn't be an issue if you filed a PR because there would be a place there for discussion...

[deveshks]

I'll take a look at some point. (I wrote those tests so should be able to help you.) By the way, I think it's better to file PR's even if the tests aren't passing. You can mark them WIP (work in progress) or use GitHub's "Draft" indicator. Otherwise, it's harder to review and give feedback on code. Like, right now you're having to clutter the issue comments with information about your code, but that wouldn't be an issue if you filed a PR because there would be a place there for discussion...

Agreed, I have gone ahead and filed the PR https://github.com/pypa/pip/pull/8318 , and we can continue the discussion there instead of cluttering the issue here. Apologies for the noise.