mirror of
https://github.com/PowerShell/PowerShell
synced 2026-06-08 12:12:50 +00:00
Improve verbose and debug logging level messaging in web cmdlets (#25510)
This commit is contained in:
Justin Grote
+12
-2
@@ -9,7 +9,7 @@ using System.Management.Automation;
|
||||
using System.Net.Http;
|
||||
using System.Net.Http.Headers;
|
||||
using System.Text;
|
||||
|
||||
using Humanizer;
|
||||
using Microsoft.Win32;
|
||||
|
||||
namespace Microsoft.PowerShell.Commands
|
||||
@@ -21,8 +21,15 @@ namespace Microsoft.PowerShell.Commands
|
||||
// ContentType may not exist in response header. Return null if not.
|
||||
internal static string? GetContentType(HttpResponseMessage response) => response.Content.Headers.ContentType?.MediaType;
|
||||
|
||||
internal static string? GetContentType(HttpRequestMessage request) => request.Content?.Headers.ContentType?.MediaType;
|
||||
|
||||
internal static Encoding GetDefaultEncoding() => Encoding.UTF8;
|
||||
|
||||
internal static string GetFriendlyContentLength(long? length) =>
|
||||
length.HasValue
|
||||
? $"{length.Value.Bytes().Humanize()} ({length.Value:#,0} bytes)"
|
||||
: "unknown size";
|
||||
|
||||
internal static StringBuilder GetRawContentHeader(HttpResponseMessage response)
|
||||
{
|
||||
StringBuilder raw = new();
|
||||
@@ -133,10 +140,13 @@ namespace Microsoft.PowerShell.Commands
|
||||
|| contentType.Equals("application/xml-external-parsed-entity", StringComparison.OrdinalIgnoreCase)
|
||||
|| contentType.Equals("application/xml-dtd", StringComparison.OrdinalIgnoreCase)
|
||||
|| contentType.EndsWith("+xml", StringComparison.OrdinalIgnoreCase);
|
||||
|
||||
|
||||
return isXml;
|
||||
}
|
||||
|
||||
internal static bool IsTextBasedContentType([NotNullWhen(true)] string? contentType)
|
||||
=> IsText(contentType) || IsJson(contentType) || IsXml(contentType);
|
||||
|
||||
#endregion Internal Methods
|
||||
}
|
||||
}
|
||||
|
||||
+10
-6
@@ -99,18 +99,22 @@ namespace Microsoft.PowerShell.Commands
|
||||
string? characterSet = WebResponseHelper.GetCharacterSet(response);
|
||||
string str = StreamHelper.DecodeStream(responseStream, characterSet, out Encoding encoding, perReadTimeout, _cancelToken.Token);
|
||||
|
||||
string encodingVerboseName;
|
||||
string friendlyName = "unknown";
|
||||
string encodingWebName = "unknown";
|
||||
string encodingPage = encoding.CodePage == -1 ? "unknown" : encoding.CodePage.ToString();
|
||||
try
|
||||
{
|
||||
encodingVerboseName = encoding.HeaderName;
|
||||
// NOTE: These are getter methods that may possibly throw a NotSupportedException exception,
|
||||
// hence the try/catch
|
||||
encodingWebName = encoding.WebName;
|
||||
friendlyName = encoding.EncodingName;
|
||||
}
|
||||
catch
|
||||
{
|
||||
encodingVerboseName = string.Empty;
|
||||
}
|
||||
|
||||
// NOTE: Tests use this verbose output to verify the encoding.
|
||||
WriteVerbose($"Content encoding: {encodingVerboseName}");
|
||||
// NOTE: Tests use this debug output to verify the encoding.
|
||||
WriteDebug($"WebResponse content encoding: {encodingWebName} ({friendlyName}) CodePage: {encodingPage}");
|
||||
|
||||
// Determine the response type
|
||||
RestReturnType returnType = CheckReturnType(response);
|
||||
@@ -140,7 +144,7 @@ namespace Microsoft.PowerShell.Commands
|
||||
|
||||
responseStream.Position = 0;
|
||||
}
|
||||
|
||||
|
||||
if (ShouldSaveToOutFile)
|
||||
{
|
||||
string outFilePath = WebResponseHelper.GetOutFilePath(response, _qualifiedOutFile);
|
||||
|
||||
+217
-31
@@ -93,6 +93,11 @@ namespace Microsoft.PowerShell.Commands
|
||||
{
|
||||
#region Fields
|
||||
|
||||
/// <summary>
|
||||
/// Used to prefix the headers in debug and verbose messaging.
|
||||
/// </summary>
|
||||
internal const string DebugHeaderPrefix = "--- ";
|
||||
|
||||
/// <summary>
|
||||
/// Cancellation token source.
|
||||
/// </summary>
|
||||
@@ -1280,40 +1285,27 @@ namespace Microsoft.PowerShell.Commands
|
||||
_cancelToken = new CancellationTokenSource();
|
||||
try
|
||||
{
|
||||
long requestContentLength = request.Content is null ? 0 : request.Content.Headers.ContentLength.Value;
|
||||
if (IsWriteVerboseEnabled())
|
||||
{
|
||||
WriteWebRequestVerboseInfo(currentRequest);
|
||||
}
|
||||
|
||||
string reqVerboseMsg = string.Format(
|
||||
CultureInfo.CurrentCulture,
|
||||
WebCmdletStrings.WebMethodInvocationVerboseMsg,
|
||||
request.Version,
|
||||
request.Method,
|
||||
requestContentLength);
|
||||
|
||||
WriteVerbose(reqVerboseMsg);
|
||||
|
||||
string reqDebugMsg = string.Format(
|
||||
CultureInfo.CurrentCulture,
|
||||
WebCmdletStrings.WebRequestDebugMsg,
|
||||
request.ToString());
|
||||
|
||||
WriteDebug(reqDebugMsg);
|
||||
if (IsWriteDebugEnabled())
|
||||
{
|
||||
WriteWebRequestDebugInfo(currentRequest);
|
||||
}
|
||||
|
||||
response = client.SendAsync(currentRequest, HttpCompletionOption.ResponseHeadersRead, _cancelToken.Token).GetAwaiter().GetResult();
|
||||
|
||||
string contentType = ContentHelper.GetContentType(response);
|
||||
long? contentLength = response.Content.Headers.ContentLength;
|
||||
string respVerboseMsg = contentLength is null
|
||||
? string.Format(CultureInfo.CurrentCulture, WebCmdletStrings.WebResponseNoSizeVerboseMsg, response.Version, contentType)
|
||||
: string.Format(CultureInfo.CurrentCulture, WebCmdletStrings.WebResponseVerboseMsg, response.Version, contentLength, contentType);
|
||||
if (IsWriteVerboseEnabled())
|
||||
{
|
||||
WriteWebResponseVerboseInfo(response);
|
||||
}
|
||||
|
||||
WriteVerbose(respVerboseMsg);
|
||||
|
||||
string resDebugMsg = string.Format(
|
||||
CultureInfo.CurrentCulture,
|
||||
WebCmdletStrings.WebResponseDebugMsg,
|
||||
response.ToString());
|
||||
|
||||
WriteDebug(resDebugMsg);
|
||||
if (IsWriteDebugEnabled())
|
||||
{
|
||||
WriteWebResponseDebugInfo(response);
|
||||
}
|
||||
}
|
||||
catch (TaskCanceledException ex)
|
||||
{
|
||||
@@ -1437,13 +1429,206 @@ namespace Microsoft.PowerShell.Commands
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(response);
|
||||
}
|
||||
|
||||
#endregion Virtual Methods
|
||||
|
||||
#region Helper Methods
|
||||
|
||||
#nullable enable
|
||||
internal static TimeSpan ConvertTimeoutSecondsToTimeSpan(int timeout) => timeout > 0 ? TimeSpan.FromSeconds(timeout) : Timeout.InfiniteTimeSpan;
|
||||
|
||||
private void WriteWebRequestVerboseInfo(HttpRequestMessage request)
|
||||
{
|
||||
try
|
||||
{
|
||||
// Typical Basic Example: 'WebRequest: v1.1 POST https://httpstat.us/200 with query length 6'
|
||||
StringBuilder verboseBuilder = new(128);
|
||||
|
||||
// "Redact" the query string from verbose output, the details will be visible in Debug output
|
||||
string uriWithoutQuery = request.RequestUri?.GetLeftPart(UriPartial.Path) ?? string.Empty;
|
||||
verboseBuilder.Append($"WebRequest: v{request.Version} {request.Method} {uriWithoutQuery}");
|
||||
if (request.RequestUri?.Query is not null && request.RequestUri.Query.Length > 1)
|
||||
{
|
||||
verboseBuilder.Append($" with query length {request.RequestUri.Query.Length - 1}");
|
||||
}
|
||||
|
||||
string? requestContentType = ContentHelper.GetContentType(request);
|
||||
if (requestContentType is not null)
|
||||
{
|
||||
verboseBuilder.Append($" with {requestContentType} payload");
|
||||
}
|
||||
|
||||
long? requestContentLength = request.Content?.Headers?.ContentLength;
|
||||
if (requestContentLength is not null)
|
||||
{
|
||||
verboseBuilder.Append($" with body size {ContentHelper.GetFriendlyContentLength(requestContentLength)}");
|
||||
}
|
||||
if (OutFile is not null)
|
||||
{
|
||||
verboseBuilder.Append($" output to {QualifyFilePath(OutFile)}");
|
||||
}
|
||||
|
||||
WriteVerbose(verboseBuilder.ToString().Trim());
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Just in case there are any edge cases we missed, we don't break workflows with an exception
|
||||
WriteVerbose($"Failed to Write WebRequest Verbose Info: {ex} {ex.StackTrace}");
|
||||
}
|
||||
}
|
||||
|
||||
private void WriteWebRequestDebugInfo(HttpRequestMessage request)
|
||||
{
|
||||
try
|
||||
{
|
||||
// Typical basic example:
|
||||
// WebRequest Detail
|
||||
// ---QUERY
|
||||
// test = 5
|
||||
// --- HEADERS
|
||||
// User - Agent: Mozilla / 5.0, (Linux;Ubuntu 24.04.2 LTS;en - US), PowerShell / 7.6.0
|
||||
StringBuilder debugBuilder = new("WebRequest Detail" + Environment.NewLine, 512);
|
||||
|
||||
if (!string.IsNullOrEmpty(request.RequestUri?.Query))
|
||||
{
|
||||
debugBuilder.Append(DebugHeaderPrefix).AppendLine("QUERY");
|
||||
string[] queryParams = request.RequestUri.Query.TrimStart('?').Split('&');
|
||||
debugBuilder
|
||||
.AppendJoin(Environment.NewLine, queryParams)
|
||||
.AppendLine()
|
||||
.AppendLine();
|
||||
}
|
||||
|
||||
debugBuilder.Append(DebugHeaderPrefix).AppendLine("HEADERS");
|
||||
|
||||
foreach (var headerSet in new HttpHeaders?[] { request.Headers, request.Content?.Headers })
|
||||
{
|
||||
if (headerSet is null)
|
||||
{
|
||||
continue;
|
||||
}
|
||||
|
||||
debugBuilder.AppendLine(headerSet.ToString());
|
||||
}
|
||||
|
||||
if (request.Content is not null)
|
||||
{
|
||||
debugBuilder
|
||||
.Append(DebugHeaderPrefix).AppendLine("BODY")
|
||||
.AppendLine(request.Content switch
|
||||
{
|
||||
StringContent stringContent => stringContent
|
||||
.ReadAsStringAsync(_cancelToken.Token)
|
||||
.GetAwaiter().GetResult(),
|
||||
MultipartFormDataContent multipartContent => "=> Multipart Form Content"
|
||||
+ Environment.NewLine
|
||||
+ multipartContent.ReadAsStringAsync(_cancelToken.Token)
|
||||
.GetAwaiter().GetResult(),
|
||||
ByteArrayContent byteContent => InFile is not null
|
||||
? "[Binary content: "
|
||||
+ ContentHelper.GetFriendlyContentLength(byteContent.Headers.ContentLength)
|
||||
+ "]"
|
||||
: byteContent.ReadAsStringAsync(_cancelToken.Token).GetAwaiter().GetResult(),
|
||||
StreamContent streamContent =>
|
||||
"[Stream content: " + ContentHelper.GetFriendlyContentLength(streamContent.Headers.ContentLength) + "]",
|
||||
_ => "[Unknown content type]",
|
||||
})
|
||||
.AppendLine();
|
||||
}
|
||||
|
||||
WriteDebug(debugBuilder.ToString().Trim());
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Just in case there are any edge cases we missed, we don't break workflows with an exception
|
||||
WriteVerbose($"Failed to Write WebRequest Debug Info: {ex} {ex.StackTrace}");
|
||||
}
|
||||
}
|
||||
|
||||
private void WriteWebResponseVerboseInfo(HttpResponseMessage response)
|
||||
{
|
||||
try
|
||||
{
|
||||
// Typical basic example: WebResponse: 200 OK with text/plain payload body size 6 B (6 bytes)
|
||||
StringBuilder verboseBuilder = new(128);
|
||||
verboseBuilder.Append($"WebResponse: {(int)response.StatusCode} {response.ReasonPhrase ?? response.StatusCode.ToString()}");
|
||||
|
||||
string? responseContentType = ContentHelper.GetContentType(response);
|
||||
if (responseContentType is not null)
|
||||
{
|
||||
verboseBuilder.Append($" with {responseContentType} payload");
|
||||
}
|
||||
|
||||
long? responseContentLength = response.Content?.Headers?.ContentLength;
|
||||
if (responseContentLength is not null)
|
||||
{
|
||||
verboseBuilder.Append($" with body size {ContentHelper.GetFriendlyContentLength(responseContentLength)}");
|
||||
}
|
||||
|
||||
WriteVerbose(verboseBuilder.ToString().Trim());
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Just in case there are any edge cases we missed, we don't break workflows with an exception
|
||||
WriteVerbose($"Failed to Write WebResponse Verbose Info: {ex} {ex.StackTrace}");
|
||||
}
|
||||
}
|
||||
|
||||
private void WriteWebResponseDebugInfo(HttpResponseMessage response)
|
||||
{
|
||||
try
|
||||
{
|
||||
// Typical basic example
|
||||
// WebResponse Detail
|
||||
// --- HEADERS
|
||||
// Date: Fri, 09 May 2025 18:06:44 GMT
|
||||
// Server: Kestrel
|
||||
// Set-Cookie: ARRAffinity=ee0b467f95b53d8dcfe48aeeb4173f93cf819be6e4721f434341647f4695039d;Path=/;HttpOnly;Secure;Domain=httpstat.us, ARRAffinitySameSite=ee0b467f95b53d8dcfe48aeeb4173f93cf819be6e4721f434341647f4695039d;Path=/;HttpOnly;SameSite=None;Secure;Domain=httpstat.us
|
||||
// Strict-Transport-Security: max-age=2592000
|
||||
// Request-Context: appId=cid-v1:3548b0f5-7f75-492f-82bb-b6eb0e864e53
|
||||
// Content-Length: 6
|
||||
// Content-Type: text/plain
|
||||
// --- BODY
|
||||
// 200 OK
|
||||
StringBuilder debugBuilder = new("WebResponse Detail" + Environment.NewLine, 512);
|
||||
|
||||
debugBuilder.Append(DebugHeaderPrefix).AppendLine("HEADERS");
|
||||
|
||||
foreach (var headerSet in new HttpHeaders?[] { response.Headers, response.Content?.Headers })
|
||||
{
|
||||
if (headerSet is null)
|
||||
{
|
||||
continue;
|
||||
}
|
||||
|
||||
debugBuilder.AppendLine(headerSet.ToString());
|
||||
}
|
||||
|
||||
if (response.Content is not null)
|
||||
{
|
||||
debugBuilder.Append(DebugHeaderPrefix).AppendLine("BODY");
|
||||
|
||||
if (ContentHelper.IsTextBasedContentType(ContentHelper.GetContentType(response)))
|
||||
{
|
||||
debugBuilder.AppendLine(
|
||||
response.Content.ReadAsStringAsync(_cancelToken.Token)
|
||||
.GetAwaiter().GetResult());
|
||||
}
|
||||
else
|
||||
{
|
||||
string friendlyContentLength = ContentHelper.GetFriendlyContentLength(
|
||||
response.Content?.Headers?.ContentLength);
|
||||
debugBuilder.AppendLine($"[Binary content: {friendlyContentLength}]");
|
||||
}
|
||||
}
|
||||
|
||||
WriteDebug(debugBuilder.ToString().Trim());
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Just in case there are any edge cases we missed, we don't break workflows with an exception
|
||||
WriteVerbose($"Failed to Write WebResponse Debug Info: {ex} {ex.StackTrace}");
|
||||
}
|
||||
}
|
||||
|
||||
private Uri PrepareUri(Uri uri)
|
||||
{
|
||||
uri = CheckProtocol(uri);
|
||||
@@ -1478,6 +1663,7 @@ namespace Microsoft.PowerShell.Commands
|
||||
|
||||
return uri.IsAbsoluteUri ? uri : new Uri("http://" + uri.OriginalString);
|
||||
}
|
||||
#nullable restore
|
||||
|
||||
private string QualifyFilePath(string path) => PathUtils.ResolveFilePath(filePath: path, command: this, isLiteralPath: true);
|
||||
|
||||
|
||||
@@ -234,21 +234,9 @@
|
||||
<data name="FollowingRelLinkVerboseMsg" xml:space="preserve">
|
||||
<value>Following rel link {0}</value>
|
||||
</data>
|
||||
<data name="WebMethodInvocationVerboseMsg" xml:space="preserve">
|
||||
<value>Requested HTTP/{0} {1} with {2}-byte payload</value>
|
||||
</data>
|
||||
<data name="WebMethodResumeFailedVerboseMsg" xml:space="preserve">
|
||||
<value>The remote server indicated it could not resume downloading. The local file will be overwritten.</value>
|
||||
</data>
|
||||
<data name="WebResponseVerboseMsg" xml:space="preserve">
|
||||
<value>Received HTTP/{0} {1}-byte response of content type {2}</value>
|
||||
</data>
|
||||
<data name="WebRequestDebugMsg" xml:space="preserve">
|
||||
<value>Request {0}</value>
|
||||
</data>
|
||||
<data name="WebResponseDebugMsg" xml:space="preserve">
|
||||
<value>Response {0}</value>
|
||||
</data>
|
||||
<data name="WebResponseNoSizeVerboseMsg" xml:space="preserve">
|
||||
<value>Received HTTP/{0} response of content type {1} of unknown size</value>
|
||||
</data>
|
||||
|
||||
@@ -284,7 +284,7 @@ function ExecuteWebRequest {
|
||||
return $result
|
||||
}
|
||||
|
||||
[string] $verboseEncodingPrefix = 'Content encoding: '
|
||||
[string] $debugEncodingPrefix = 'WebResponse content encoding: '
|
||||
# This function calls Invoke-WebRequest with the given uri and
|
||||
# parses the verbose output to determine the encoding used for the content.
|
||||
function ExecuteRestMethod {
|
||||
@@ -297,37 +297,39 @@ function ExecuteRestMethod {
|
||||
$UseBasicParsing
|
||||
)
|
||||
$result = @{Output = $null; Error = $null; Encoding = $null; Content = $null}
|
||||
$verbosePreferenceSave = $VerbosePreference
|
||||
$VerbosePreference = 'Continue'
|
||||
$debugPreferenceSave = $DebugPreference
|
||||
$DebugPreference = 'Continue'
|
||||
try {
|
||||
$verboseFile = Join-Path $TestDrive -ChildPath ExecuteRestMethod.verbose.txt
|
||||
$result.Output = Invoke-RestMethod -Uri $Uri -UseBasicParsing:$UseBasicParsing.IsPresent -Verbose 4>$verboseFile
|
||||
$debugFile = Join-Path $TestDrive -ChildPath ExecuteRestMethod.debug.txt
|
||||
$result.Output = Invoke-RestMethod -Uri $Uri -UseBasicParsing:$UseBasicParsing.IsPresent 5>$debugFile
|
||||
$result.Content = $result.Output
|
||||
|
||||
if (Test-Path -Path $verboseFile) {
|
||||
$result.Verbose = Get-Content -Path $verboseFile
|
||||
foreach ($item in $result.Verbose) {
|
||||
# Invoke-RestMethod does not return encoding as part of an object, only in debug output, so we parse the debug output for the purposes of verifying the test.
|
||||
# This debug output is defined in InvokeRestMethodCommand.Common.cs ProcessResponse()
|
||||
if (Test-Path -Path $debugFile) {
|
||||
$result.Debug = Get-Content -Path $debugFile
|
||||
foreach ($item in $result.Debug) {
|
||||
$line = $item.Trim()
|
||||
if ($line.StartsWith($verboseEncodingPrefix)) {
|
||||
$encodingName = $item.SubString($verboseEncodingPrefix.Length).Trim()
|
||||
if ($line.StartsWith($debugEncodingPrefix)) {
|
||||
$encodingName = [int]::Parse($item.SubString($EncodingPrefix.Length).Split('CodePage: ')[1].Trim())
|
||||
$result.Encoding = [System.Text.Encoding]::GetEncoding($encodingName)
|
||||
break
|
||||
}
|
||||
}
|
||||
if ($result.Encoding -eq $null) {
|
||||
throw "Encoding not found in verbose output. Lines: $($result.Verbose.Count) Content:$($result.Verbose)"
|
||||
if ($null -eq $result.Encoding) {
|
||||
throw "Encoding not found in debug output. Lines: $($result.Debug.Count) Content:$($result.Debug)"
|
||||
}
|
||||
}
|
||||
|
||||
if ($result.Verbose -eq $null) {
|
||||
throw "No verbose output was found"
|
||||
if ($null -eq $result.Debug) {
|
||||
throw "No debug output was found"
|
||||
}
|
||||
} catch {
|
||||
$result.Error = $_ | Select-Object * | Out-String
|
||||
} finally {
|
||||
$VerbosePreference = $verbosePreferenceSave
|
||||
if (Test-Path -Path $verboseFile) {
|
||||
Remove-Item -Path $verboseFile -ErrorAction SilentlyContinue
|
||||
$DebugPreference = $debugPreferenceSave
|
||||
if (Test-Path -Path $debugFile) {
|
||||
Remove-Item -Path $debugFile -ErrorAction SilentlyContinue
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user