Skip to content

Conversation

@iangelak
Copy link
Contributor

@iangelak iangelak commented Nov 11, 2025

External command output lacked package prefixes on continuation lines, making logs hard to grep in parallel builds.

Solution: Added get_log_prefix() helper to extract package context. FromagerLogRecord prefixes the first line, str.replace() handles continuation lines.

Fixes: #753

@iangelak iangelak requested a review from a team as a code owner November 11, 2025 20:11
@mergify mergify bot added the ci label Nov 11, 2025
@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch from 7e826d6 to f791867 Compare November 11, 2025 20:15
@dhellmann
Copy link
Member

When I run an e2e test with this change, I do see the prefix as expected:

2025-11-11 18:22:11,813 DEBUG:fromager.external_commands:73: setuptools: running:  uv venv --verbose --python '/Users/dhellmann/Library/Application Support/hatch/env/virtual/fromager/V7Nl9Nl1/e2e/bin/python' --no-project /Users/dhellmann/Devel/fromager/fromager/e2e-output/work-dir/setuptools-80.9.0/build-3.14.0 in .
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG uv 0.9.8 (85c5d3228 2025-11-07)
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG Acquired shared lock for `/Users/dhellmann/.cache/uv`
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG Using Python request `/Users/dhellmann/Library/Application Support/hatch/env/virtual/fromager/V7Nl9Nl1/e2e/bin/python` from explicit request
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG Checking for Python interpreter at path `/Users/dhellmann/Library/Application Support/hatch/env/virtual/fromager/V7Nl9Nl1/e2e/bin/python`
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: Using CPython 3.14.0 interpreter at: /Users/dhellmann/Library/Application Support/hatch/env/virtual/fromager/V7Nl9Nl1/e2e/bin/python
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: Creating virtual environment at: e2e-output/work-dir/setuptools-80.9.0/build-3.14.0
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG Using base executable for virtual environment: /opt/homebrew/Cellar/[email protected]/3.14.0_1/Frameworks/Python.framework/Versions/3.14/bin/python3.14
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: Activate with: source e2e-output/work-dir/setuptools-80.9.0/build-3.14.0/bin/activate
2025-11-11 18:22:11,828 DEBUG:fromager.external_commands:130: setuptools: DEBUG Released lock at `/Users/dhellmann/.cache/uv/.lock`
2025-11-11 18:22:11,828 INFO:fromager.build_environment:189: setuptools: created build environment in /Users/dhellmann/Devel/fromager/fromager/e2e-output/work-dir/setuptools-80.9.0/build-3.14.0

What can we do to make it more obvious that those lines are the output of the uv command, and not fromager itself?

@tiran
Copy link
Collaborator

tiran commented Nov 12, 2025

I'm worried that this change is going to make the logs even harder to read, especially when we build packages in parallel. Currently the entire output of an external command is logged as one multi-line string. With your change, the output is split into individual lines and every line is logged on its own. If Fromager is building 10 packages in parallel, the output of all 10 builds are multiplexed. It makes the output very hard to read.

@iangelak
Copy link
Contributor Author

@dhellmann I' ll try to add UV in the prefix to distinguish its printouts from Fromager's.
@tiran I see what you mean. Maybe a dumb idea but could we introduce a lock (only for these printouts) that would serialize these build logs? This way all the messages for one build will be placed together.

@tiran
Copy link
Collaborator

tiran commented Nov 12, 2025

You could add a lock, but then you'd have to figure out how to do proper locking without blocking other threads.

There is a much, much simpler way to solve the problem: rewrite the output, then log the entire output in one logger call. You can archive this with just one str method.

@dhellmann
Copy link
Member

You could add a lock, but then you'd have to figure out how to do proper locking without blocking other threads.

There is a much, much simpler way to solve the problem: rewrite the output, then log the entire output in one logger call. You can archive this with just one str method.

Yeah, I like this approach.

@iangelak
Copy link
Contributor Author

If I understood correctly, @tiran you are suggesting to first split the output to lines, then add the prefix to each line and then concatenate all lines back to one string and print that right?

@tiran
Copy link
Collaborator

tiran commented Nov 12, 2025

Yes, something like that. But instead of splitting the string, you can archive the goal with just str method call.

@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch from f791867 to c7ddc85 Compare November 13, 2025 16:01
@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch from c7ddc85 to 70ba61e Compare November 17, 2025 14:00
@iangelak
Copy link
Contributor Author

Let me know if these changes are good.

@iangelak iangelak requested review from dhellmann and tiran November 19, 2025 14:39
tiran
tiran previously requested changes Nov 24, 2025
@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch 3 times, most recently from 55c47b0 to d0dd682 Compare November 25, 2025 18:30
@iangelak iangelak requested a review from tiran November 25, 2025 19:39
Copy link
Contributor

@rd4398 rd4398 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks okay to me. I see Doug and Christian had comments on previous versions of this MR. I will leave it to them for final approval

@LalatenduMohanty
Copy link
Member

@iangelak The commit message is too long, also there are more comments in the code than required. We do not need comments unless it is a must have. Also lets reduce the commit message to 2 to 3 lines which is more human readable than long texts.

@LalatenduMohanty
Copy link
Member

@iangelak Do you have logs to compare before and after (this patch)? If yes, please put it in the PR so that it is easier for the reviewers to see the difference.

@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch 2 times, most recently from 78a4950 to b792bd6 Compare December 4, 2025 16:09
@iangelak
Copy link
Contributor Author

iangelak commented Dec 4, 2025

@iangelak Do you have logs to compare before and after (this patch)? If yes, please put it in the PR so that it is easier for the reviewers to see the difference.

Yes of course here is an example before and after the patch:

=== WITHOUT PATCH (OLD BEHAVIOR) ===
ERROR: numpy-1.26.0: command failed with exit code 1: sh -c 'printf '"'"'Resolving dependencies...
Failed to download
Retrying connection'"'"' && exit 1'
Resolving dependencies...
Failed to download
Retrying connection

and

=== WITH PATCH ===
ERROR: numpy-1.26.0: command failed with exit code 1: sh -c 'printf '"'"'Resolving dependencies...
Failed to download
Retrying connection'"'"' && exit 1'
numpy-1.26.0: Resolving dependencies...
numpy-1.26.0: Failed to download
numpy-1.26.0: Retrying connection

@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch from b792bd6 to ec8aada Compare December 4, 2025 16:40
@dhellmann
Copy link
Member

This implementation looks good to me. I'll leave the PR open because @LalatenduMohanty and @tiran both had comments as well, but let's try to get this merged by early next week so we can cut a release.

@LalatenduMohanty
Copy link
Member

@iangelak Thanks for fixing the commits. Appreciate it.

External command output lacked package prefixes on continuation lines,
making logs hard to grep in parallel builds.

Solution: Added get_log_prefix() helper to extract package context.
FromagerLogRecord prefixes the first line, str.replace() handles
continuation lines.

Fixes: python-wheel-build#753

Co-authored-by: Claude <[email protected]>

Signed-off-by: Ioannis Angelakopoulos <[email protected]>
@iangelak iangelak force-pushed the 753-uv-prefix-debug-output branch from ec8aada to 792432c Compare December 5, 2025 15:23
@dhellmann dhellmann dismissed tiran’s stale review December 7, 2025 15:38

I think all of the review comments from @tiran are addressed so I am clearing the change request so we can merge this and cut a release.

@dhellmann
Copy link
Member

@Mergifyio refresh

@mergify
Copy link
Contributor

mergify bot commented Dec 7, 2025

refresh

✅ Pull request refreshed

@mergify mergify bot merged commit e1479d7 into python-wheel-build:main Dec 7, 2025
112 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

debug output from uv is not prefixed with the package name so parallel builds are hard to debug

5 participants