Skip to content

fix: preserve workunit log level in local cache metadata update#23251

Merged
benjyw merged 1 commit intopantsbuild:mainfrom
altana-ai:jwb/fix-scheduling-workunit-log-level
Apr 14, 2026
Merged

fix: preserve workunit log level in local cache metadata update#23251
benjyw merged 1 commit intopantsbuild:mainfrom
altana-ai:jwb/fix-scheduling-workunit-log-level

Conversation

@jasonwbarnett
Copy link
Copy Markdown
Contributor

@jasonwbarnett jasonwbarnett commented Apr 14, 2026

Problem

When a process runs (e.g. generate-lockfiles), the local cache runner updates the "Scheduling:" workunit metadata to attach cache digests. As a side effect, it overrides the workunit log level to Info, regardless of its original level. Since ExecuteProcess workunits intentionally start at Debug (to avoid rendering until execution actually begins), this promotion causes duplicate INFO-level output:

23:22:27.30 [INFO] Starting: Generate lockfile for pytest
23:22:53.66 [INFO] Completed: Generate lockfile for pytest (26.4s)
23:22:53.66 [INFO] Completed: Scheduling: Generate lockfile for pytest (26.4s)

The third line is redundant — the scheduling workunit is a wrapper whose duration mirrors its child.

Root Cause

This was inadvertently introduced in #22212, which added Action/Command digest metadata to workunits. The update_metadata call needed to attach local_command and local_action digests, but the closure also hardcoded Level::Info as the new level — discarding the original. The PR was focused on metadata, not log levels, and the level override was not discussed in review.

Solution

Preserve the workunit's original log level when updating cache metadata, instead of unconditionally overriding it to Level::Info. The metadata update only needs to set local_command and local_action — it has no reason to change the log level.

Result

Default (INFO-level) output is now clean:

23:22:27.30 [INFO] Starting: Generate lockfile for pytest
23:22:53.66 [INFO] Completed: Generate lockfile for pytest

The "Scheduling:" message remains visible at -ldebug for debugging purposes.

LLM Disclosure

This PR was written with Amp (Claude). The LLM diagnosed the root cause by tracing the workunit level flow through the codebase, identified the accidental Level::Info override in #22212, and wrote the one-line fix. I reviewed the diagnosis and fix, validated it by running Pants from sources against our monorepo, and confirmed the duplicate log line no longer appears.

Related: #22992

@jasonwbarnett jasonwbarnett force-pushed the jwb/fix-scheduling-workunit-log-level branch from 5583c82 to e890606 Compare April 14, 2026 15:59
@jasonwbarnett jasonwbarnett changed the title fix: keep scheduling workunit at Debug level to avoid duplicate INFO logs fix: preserve workunit log level in local cache metadata update Apr 14, 2026
…logs

The local cache runner was promoting the ExecuteProcess (Scheduling:)
workunit from Debug to Info when setting cache metadata. This caused
"Completed: Scheduling: ..." to appear at INFO alongside the child
"Completed: ..." message, producing duplicate log noise.

Keep the scheduling workunit at Debug so only the actual process
execution workunit logs at INFO.

Co-authored-by: Amp <amp@ampcode.com>
Amp-Thread-ID: https://ampcode.com/threads/T-019d8ca2-81aa-7538-a6ef-7f44d71da184
Copy link
Copy Markdown
Contributor

@benjyw benjyw left a comment

Choose a reason for hiding this comment

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

Good find!

If you used an LLM for this can you update the PR with the disclosure? Thanks

@jasonwbarnett
Copy link
Copy Markdown
Contributor Author

Good find!

If you used an LLM for this can you update the PR with the disclosure? Thanks

Done. Let me know if that's not what you meant.

@benjyw
Copy link
Copy Markdown
Contributor

benjyw commented Apr 14, 2026

Good find!
If you used an LLM for this can you update the PR with the disclosure? Thanks

Done. Let me know if that's not what you meant.

Yep, that was perfect, in line with our relatively new disclosure policy (which hasn't been published to the docs yet for some reason, will look into that). Thanks.

@benjyw benjyw merged commit 1814531 into pantsbuild:main Apr 14, 2026
25 checks passed
@jasonwbarnett jasonwbarnett deleted the jwb/fix-scheduling-workunit-log-level branch April 15, 2026 23:16
jasonwbarnett pushed a commit to altana-ai/pants that referenced this pull request Apr 15, 2026
…root cause

PR pantsbuild#23251 fixed the "Scheduling:" workunit being promoted to INFO,
so the log_duration mechanism to suppress duplicate durations is no
longer needed. Duration is now shown unconditionally for completed
and canceled workunits.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants