diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index 81c443adf49..f5dc0fecf78 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/src/pip/_internal/cli/base_command.py @@ -166,7 +166,7 @@ def exc_logging_wrapper(*args: Any) -> int: assert isinstance(status, int) return status except DiagnosticPipError as exc: - logger.error("[present-diagnostic]", exc) + logger.error("[present-diagnostic] %s", exc) logger.debug("Exception information:", exc_info=True) return ERROR diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 1c0cd8e261e..6e001c5d63c 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -152,7 +152,7 @@ def emit(self, record: logging.LogRecord) -> None: style: Optional[Style] = None # If we are given a diagnostic error to present, present it with indentation. - if record.msg == "[present-diagnostic]" and len(record.args) == 1: + if record.msg == "[present-diagnostic] %s" and len(record.args) == 1: diagnostic_error: DiagnosticPipError = record.args[0] # type: ignore[index] assert isinstance(diagnostic_error, DiagnosticPipError) diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 395bbca418f..b5b762418f5 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -209,7 +209,7 @@ def call_subprocess( output_lines=all_output if not showing_subprocess else None, ) if log_failed_cmd: - subprocess_logger.error("[present-diagnostic]", error) + subprocess_logger.error("[present-diagnostic] %s", error) subprocess_logger.verbose( "[bold magenta]full command[/]: [blue]%s[/]", escape(format_command_args(cmd)), diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index 0ff34bca653..c14c407d2df 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/tests/unit/test_utils_subprocess.py @@ -69,8 +69,8 @@ def test_call_subprocess_stdout_only( assert out in expected captured = capfd.readouterr() assert captured.err == "" - assert log == ["Running %s", "out", "err"] or log == [ - "Running %s", + assert log == ["Running command %s", "out", "err"] or log == [ + "Running command %s", "err", "out", ] @@ -246,14 +246,23 @@ def test_info_logging__subprocess_error( spinner=spinner, ) result = None - exc_message = str(exc.value) - assert exc_message.startswith("Command errored out with exit status 1: ") - assert exc_message.endswith("Check the logs for full command output.") + exception = exc.value + assert exception.reference == "subprocess-exited-with-error" + assert "exit code: 1" in exception.message + assert exception.note_stmt + assert "not a problem with pip" in exception.note_stmt + # Check that the process outout is captured, and would be shown. + assert exception.context + assert "Hello\n" in exception.context + assert "fail\n" in exception.context + assert "world\n" in exception.context expected = ( None, [ - ("pip.subprocessor", ERROR, "Complete output (3 lines):\n"), + # pytest's caplog overrides th formatter, which means that we + # won't see the message formatted through our formatters. + ("pip.subprocessor", ERROR, "[present-diagnostic]"), ], ) # The spinner should spin three times in this case since the @@ -268,33 +277,6 @@ def test_info_logging__subprocess_error( expected_spinner=(3, "error"), ) - # Do some further checking on the captured log records to confirm - # that the subprocess output was logged. - last_record = caplog.record_tuples[-1] - last_message = last_record[2] - lines = last_message.splitlines() - - # We have to sort before comparing the lines because we can't - # guarantee the order in which stdout and stderr will appear. - # For example, we observed the stderr lines coming before stdout - # in CI for PyPy 2.7 even though stdout happens first chronologically. - actual = sorted(lines) - # Test the "command" line separately because we can't test an - # exact match. - command_line = actual.pop(1) - assert actual == [ - " cwd: None", - "----------------------------------------", - "Command errored out with exit status 1:", - "Complete output (3 lines):", - "Hello", - "fail", - "world", - ], f"lines: {actual}" # Show the full output on failure. - - assert command_line.startswith(" command: ") - assert command_line.endswith('print("world"); exit("fail")\'') - def test_info_logging_with_show_stdout_true( self, capfd: pytest.CaptureFixture[str], caplog: pytest.LogCaptureFixture ) -> None: diff --git a/tests/unit/test_wheel_builder.py b/tests/unit/test_wheel_builder.py index 9562541ff55..0468273d66a 100644 --- a/tests/unit/test_wheel_builder.py +++ b/tests/unit/test_wheel_builder.py @@ -222,7 +222,6 @@ def test_format_command_result__DEBUG( "Command output:", "output line 1", "output line 2", - "----------------------------------------", ]