Skip to content

Improve verbose and debug logging level messaging in web cmdlets #25510

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 16 commits into from
Jun 11, 2025

Conversation

JustinGrote
Copy link
Contributor

@JustinGrote JustinGrote commented May 5, 2025

PR Summary

  • Moves debug message processing to separate methods to reduce GetResponse cognitive load
  • Verbose messages redesigned to a one-line summary suited for watching the HTTP transactional flow of a script/module/etc.
  • Debug messages redesigned to show query, header and body content, and intelligently hide binary content to prevent trashing the console/logs
  • Messages are now conditionally generated based on Preference setting for performance.
  • Humanize the content payload byte length (thanks @kilasuit)
  • For Invoke-Restmethod, show the response encoding detail as a debug message

Example

image

WG Review Response

The Cmdlet WG discussed this. Since the introduction of Windows PowerShell, binary cmdlets emit both the Verbose and the Debug stream when -Debug is used. This introduces some natural redundancy when i.e. the verbose stream summarizes general operations whereas the debug stream provides more detailed info. Since both streams serve different purposes and audiences, neither one should be omitted just because of potential redundancy. As a workaround, either stream can be redirected to $null if not wanted. We continue to agree that the Debugstream is appropriate for technical details and sensitive information, whereas the Verbose stream is best for summary information.

Agreed. I have defined the intent of the messages to be as such:
Verbose: One-Liner showing the basics of what is happening, very useful for concisely tracing program flow. Sensitive information has been redacted at this level in general per Security WG comments but URL is preserved for troubleshooting purposes and basic logging flow if necessary.

Debug: Includes all sensitive information including sensitive headers which may include authentication tokens, etc. as the purpose is for debugging, not logging, and specifying DebugPreference or Debug is considered an "opt-in" for this information.

PR Context

Closes #25492

PR Checklist

@JustinGrote JustinGrote marked this pull request as draft May 5, 2025 16:29
@JustinGrote JustinGrote changed the title WebRequest Cmdlets: Improve Verbose and Debug Logging Levels and include Request Content WebRequest Cmdlets: Improve Verbose and Debug Logging Level Messaging May 5, 2025
@JustinGrote JustinGrote marked this pull request as ready for review May 5, 2025 23:02
@JustinGrote
Copy link
Contributor Author

JustinGrote commented May 5, 2025

@iSazonov ready to review!

EDIT: I lied, but now codefactor stuff is fixed.

@iSazonov
Copy link
Collaborator

iSazonov commented May 6, 2025

I wonder how many code you update. 😄 I expect you add only content output.

I like you create helper methods. But now output is too large and we must generate the output only it is requested.
I don't find method(s) to check the condition and we could create it here.
For start see how internal void WriteDebug(DebugRecord record, bool overrideInquire = false) does the check.
We can get ((MshCommandRuntime)this.CommandRuntime).DebugPreference and reuse code from internal bool WriteHelper_ShouldWrite
(All in src\System.Management.Automation\engine\MshCommandRuntime.cs)

The same for verbose. But I wouldn't waste time on verbose right now at all. But it's up to you.

Also I'd prefer to use standard TosString() for request and response. Why do we create custom implementation?

@JustinGrote
Copy link
Contributor Author

JustinGrote commented May 6, 2025

@iSazonov I had this discussion with @SeeminglyScience on discord and it is noted there isn't an ideal reliable way to check preference (if you check the first commit I was testing for it prior) and he recommended not establishing it as a pattern but rather this should be something the runtime provides as part of the PSCmdlet abstract class.

In testing the code has a non-visible impact even on large payloads if Verbose/Debug aren't specified.

I moved away from the Request/Response message toString in order to match the format as noted, and reduce redundant information between Verbose and Debug. I put the user experience in favor of the direct implementation. We can revert that if required, but I would lobby for this, especially since I try/catch potential edge cases (haven't hit any so far in testing)

EDIT: Also I made very sure not to alter existing Webcmdlet behavior, the additional areas I changed were just additive where they made sense in context, I'm very aware this is some hot-path stuff and I'm keeping the scope just to the output aspects.

@iSazonov
Copy link
Collaborator

iSazonov commented May 6, 2025

@JustinGrote Yes, we haven't std methods for the checks. I think it's important to have them because later we can add even more output (for example certificates)
One way is to create them. So I open #25514. If you could ask him in Discord to review it, that would be great.
Another way is to use simple workaround only for interactive scenario. We could check switches by more reliable way than you did - Debug.IsPresent/Verbose.IsPresent. We could use this if my PR will be blocked/rejected.

@JustinGrote
Copy link
Contributor Author

Sounds good. Do we want to merge this PR as-is for the next preview and add the conditional logic later, or wait for #25514?

@iSazonov
Copy link
Collaborator

iSazonov commented May 7, 2025

Let's wait for what Patrick says. If that PR is not approved, then let's look at switch checks. What I definitely would not like is to create these strings without a condition.
We can discuss the details for now.

Copy link
Collaborator

@iSazonov iSazonov left a comment

Choose a reason for hiding this comment

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

Mainly style comments.

@iSazonov iSazonov added the CL-General Indicates that a PR should be marked as a general cmdlet change in the Change Log label May 7, 2025
@iSazonov iSazonov self-assigned this May 7, 2025
@JustinGrote
Copy link
Contributor Author

JustinGrote commented May 7, 2025

@iSazonov thank you for the review, I will incorporate the recently merged PR and your feedback hopefully sometime this week.

@JustinGrote JustinGrote requested a review from iSazonov May 8, 2025 18:18
@JustinGrote
Copy link
Contributor Author

@iSazonov feedback incorporated and it is now conditional using the new internal IsEnabled checks

@JustinGrote JustinGrote force-pushed the justingrote/issue25492 branch from 64271c7 to 42b6d6a Compare May 8, 2025 20:13
@JustinGrote
Copy link
Contributor Author

@iSazonov changes requested implemented (I went with a nested foreach for the headers to make that easier to read), and made CodeFactor happy. I also squash rebased to a single commit so this should be mergeable now. Let me know any further issues.

@JustinGrote JustinGrote force-pushed the justingrote/issue25492 branch from 42b6d6a to 53143d9 Compare May 8, 2025 20:14
@JustinGrote JustinGrote requested a review from iSazonov May 8, 2025 22:11
@JustinGrote JustinGrote force-pushed the justingrote/issue25492 branch 3 times, most recently from 0b31ad7 to d50453c Compare May 9, 2025 19:17
@JustinGrote
Copy link
Contributor Author

@iSazonov static refactor reverted. CodeFactor however is now complaining about complex methods I didn't touch. I tried a rebase/reset and confirmed I didn't touch those methods as far as I can tell. Any idea what's going on? Is it the nullable maybe?

@JustinGrote JustinGrote requested a review from iSazonov May 9, 2025 19:21
iSazonov
iSazonov previously approved these changes May 10, 2025
Copy link
Collaborator

@iSazonov iSazonov left a comment

Choose a reason for hiding this comment

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

Please update the PR description to follow latest changes.

@iSazonov iSazonov dismissed their stale review May 10, 2025 06:02

accidentally

@JustinGrote
Copy link
Contributor Author

JustinGrote commented May 12, 2025

@iSazonov tests fixed (at least locally on my machine), the -Debug parameter was causing inquire and since Pester is run interactively, was waiting on the dialog, switched to using debugpreference.

Also adjusted encoding test to match on Codepage since we are providing it anyways, should be a much less brittle test.

@iSazonov
Copy link
Collaborator

@JustinGrote Still hang. I guess VerbosePreference is inquire.

@JustinGrote
Copy link
Contributor Author

Probably related to this, I couldn't get it to reproduce in Linux but let me do it in Windows.
image

All retries are done with recursive GetResponse added by PowerShell#19229.

The do loop was a leftover from the old way of doing things, it never actually gets triggered, and redirects previously had internal GetResponse that bypassed it, but when I unified the logic to unify the verbose messages, it now follows the flow "properly" and got stuck in the do/while instead of return the response, causing it to reuse the request and trigger an exception.
Fixes test "Invoke-WebRequest -PassThru -OutFile -Verbose File Name reflects the downloaded file name"
@microsoft-github-policy-service microsoft-github-policy-service bot added the Review - Needed The PR is being reviewed label May 23, 2025
@JustinGrote
Copy link
Contributor Author

This is still active, there's an issue somewhere in the MaximumRetry code where a request is getting reused, I haven't been able to track it down yet and need to step thru the commits to find where it's happening.

@JustinGrote
Copy link
Contributor Author

@iSazonov I found the problem. Please approve for tests to run, it should fully pass now and be mergeable.

Copy link
Collaborator

@iSazonov iSazonov left a comment

Choose a reason for hiding this comment

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

LGTM with one notice: perhaps it makes sense to remove body from debug output because it can be too large..

@JustinGrote
Copy link
Contributor Author

LGTM with one notice: perhaps it makes sense to remove body from debug output because it can be too large..

It is a possibility with text-based responses, but most extremely large responses will be binary that will be summarized.

I will suggest we merge as is and if feedback shows that it is a constant problem, we either add a fixed or user-configurable truncation option.

@JustinGrote
Copy link
Contributor Author

@iSazonov is there a reason the linux/windows AzDevOps CI are pending? I don't have any visibility that I know of.

@iSazonov
Copy link
Collaborator

/azp run PowerShell-CI-linux-packaging,PowerShell-Windows-Packaging-CI

Copy link

Azure Pipelines could not run because the pipeline triggers exclude this branch/path.

@microsoft-github-policy-service microsoft-github-policy-service bot removed the Review - Needed The PR is being reviewed label Jun 10, 2025
else
{
string friendlyContentLength = ContentHelper.GetFriendlyContentLength(
response.Content?.Headers?.ContentLength);
Copy link
Collaborator

@iSazonov iSazonov Jun 11, 2025

Choose a reason for hiding this comment

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

Headers is not null here.

Comment on lines +1460 to +1464
if (requestContentLength is not null)
{
verboseBuilder.Append($" with body size {ContentHelper.GetFriendlyContentLength(requestContentLength)}");
}
if (OutFile is not null)
Copy link
Collaborator

Choose a reason for hiding this comment

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

Style: new line is needed after brace.

@iSazonov iSazonov changed the title WebRequest Cmdlets: Improve Verbose and Debug Logging Level Messaging Improve verbose and debug logging level messaging in web cmdlets Jun 11, 2025
@iSazonov iSazonov merged commit 8185a7f into PowerShell:master Jun 11, 2025
41 checks passed
@iSazonov
Copy link
Collaborator

@JustinGrote Many thanks!

@JustinGrote JustinGrote deleted the justingrote/issue25492 branch June 11, 2025 16:46
@JustinGrote
Copy link
Contributor Author

@iSazonov same to you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
CL-General Indicates that a PR should be marked as a general cmdlet change in the Change Log
Projects
None yet
Development

Successfully merging this pull request may close these issues.

WebRequest Cmdlets: Improve Verbose and Debug Logging Levels and include Request Content
2 participants