Skip to content

Commit 53143d9

Browse files
JustinGroteJustinGrote
committed
WebRequest Cmdlets: Improve Verbose and Debug Log
- Adds a clean single-line format for Verbose and a more detailed output for Debug - Messages are optimized to only be generated if Verbose or Debug have been specified - Byte lengths are humanized for better readability - Intelligently decodes only non-binary request/response bodies Closes #25492
1 parent 957eb1b commit 53143d9

File tree

5 files changed

+226
-68
lines changed

5 files changed

+226
-68
lines changed

‎src/Microsoft.PowerShell.Commands.Utility/commands/utility/WebCmdlet/Common/ContentHelper.Common.cs‎

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@
99
using System.Net.Http;
1010
using System.Net.Http.Headers;
1111
using System.Text;
12-
12+
using Humanizer;
1313
using Microsoft.Win32;
1414

1515
namespace Microsoft.PowerShell.Commands
@@ -21,8 +21,12 @@ internal static class ContentHelper
2121
// ContentType may not exist in response header. Return null if not.
2222
internal static string? GetContentType(HttpResponseMessage response) => response.Content.Headers.ContentType?.MediaType;
2323

24+
internal static string? GetContentType(HttpRequestMessage request) => request.Content?.Headers.ContentType?.MediaType;
25+
2426
internal static Encoding GetDefaultEncoding() => Encoding.UTF8;
2527

28+
internal static string GetFriendlyContentLength(long? length) => length.HasValue ? length.Value.Bytes().Humanize() : "unknown size";
29+
2630
internal static StringBuilder GetRawContentHeader(HttpResponseMessage response)
2731
{
2832
StringBuilder raw = new();
@@ -133,10 +137,13 @@ internal static bool IsXml([NotNullWhen(true)] string? contentType)
133137
|| contentType.Equals("application/xml-external-parsed-entity", StringComparison.OrdinalIgnoreCase)
134138
|| contentType.Equals("application/xml-dtd", StringComparison.OrdinalIgnoreCase)
135139
|| contentType.EndsWith("+xml", StringComparison.OrdinalIgnoreCase);
136-
140+
137141
return isXml;
138142
}
139143

144+
internal static bool IsTextBasedContentType([NotNullWhen(true)] string? contentType)
145+
=> IsText(contentType) || IsJson(contentType) || IsXml(contentType);
146+
140147
#endregion Internal Methods
141148
}
142149
}

‎src/Microsoft.PowerShell.Commands.Utility/commands/utility/WebCmdlet/Common/InvokeRestMethodCommand.Common.cs‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -99,18 +99,20 @@ internal override void ProcessResponse(HttpResponseMessage response)
9999
string? characterSet = WebResponseHelper.GetCharacterSet(response);
100100
string str = StreamHelper.DecodeStream(responseStream, characterSet, out Encoding encoding, perReadTimeout, _cancelToken.Token);
101101

102-
string encodingVerboseName;
102+
string encodingName;
103103
try
104104
{
105-
encodingVerboseName = encoding.HeaderName;
105+
// NOTE: This is a getter method that may possibly throw a NotSupportedException exception,
106+
// hence the try/catch
107+
encodingName = encoding.HeaderName;
106108
}
107109
catch
108110
{
109-
encodingVerboseName = string.Empty;
111+
encodingName = string.Empty;
110112
}
111113

112-
// NOTE: Tests use this verbose output to verify the encoding.
113-
WriteVerbose($"Content encoding: {encodingVerboseName}");
114+
// NOTE: Tests use this debug output to verify the encoding.
115+
WriteDebug($"WebResponse content encoding: {encodingName}");
114116

115117
// Determine the response type
116118
RestReturnType returnType = CheckReturnType(response);
@@ -140,7 +142,7 @@ internal override void ProcessResponse(HttpResponseMessage response)
140142

141143
responseStream.Position = 0;
142144
}
143-
145+
144146
if (ShouldSaveToOutFile)
145147
{
146148
string outFilePath = WebResponseHelper.GetOutFilePath(response, _qualifiedOutFile);

‎src/Microsoft.PowerShell.Commands.Utility/commands/utility/WebCmdlet/Common/WebRequestPSCmdlet.Common.cs‎

Lines changed: 192 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -93,6 +93,11 @@ public abstract class WebRequestPSCmdlet : PSCmdlet, IDisposable
9393
{
9494
#region Fields
9595

96+
/// <summary>
97+
/// Used to prefix the headers in debug and verbose messaging.
98+
/// </summary>
99+
internal const string DebugHeaderPrefix = "--- ";
100+
96101
/// <summary>
97102
/// Cancellation token source.
98103
/// </summary>
@@ -1280,40 +1285,27 @@ internal virtual HttpResponseMessage GetResponse(HttpClient client, HttpRequestM
12801285
_cancelToken = new CancellationTokenSource();
12811286
try
12821287
{
1283-
long requestContentLength = request.Content is null ? 0 : request.Content.Headers.ContentLength.Value;
1284-
1285-
string reqVerboseMsg = string.Format(
1286-
CultureInfo.CurrentCulture,
1287-
WebCmdletStrings.WebMethodInvocationVerboseMsg,
1288-
request.Version,
1289-
request.Method,
1290-
requestContentLength);
1291-
1292-
WriteVerbose(reqVerboseMsg);
1293-
1294-
string reqDebugMsg = string.Format(
1295-
CultureInfo.CurrentCulture,
1296-
WebCmdletStrings.WebRequestDebugMsg,
1297-
request.ToString());
1288+
if (IsWriteVerboseEnabled())
1289+
{
1290+
WriteWebRequestVerboseInfo(request);
1291+
}
12981292

1299-
WriteDebug(reqDebugMsg);
1293+
if (IsWriteDebugEnabled())
1294+
{
1295+
WriteWebRequestDebugInfo(request);
1296+
}
13001297

13011298
response = client.SendAsync(currentRequest, HttpCompletionOption.ResponseHeadersRead, _cancelToken.Token).GetAwaiter().GetResult();
13021299

1303-
string contentType = ContentHelper.GetContentType(response);
1304-
long? contentLength = response.Content.Headers.ContentLength;
1305-
string respVerboseMsg = contentLength is null
1306-
? string.Format(CultureInfo.CurrentCulture, WebCmdletStrings.WebResponseNoSizeVerboseMsg, response.Version, contentType)
1307-
: string.Format(CultureInfo.CurrentCulture, WebCmdletStrings.WebResponseVerboseMsg, response.Version, contentLength, contentType);
1308-
1309-
WriteVerbose(respVerboseMsg);
1310-
1311-
string resDebugMsg = string.Format(
1312-
CultureInfo.CurrentCulture,
1313-
WebCmdletStrings.WebResponseDebugMsg,
1314-
response.ToString());
1300+
if (IsWriteVerboseEnabled())
1301+
{
1302+
WriteWebResponseVerboseInfo(response);
1303+
}
13151304

1316-
WriteDebug(resDebugMsg);
1305+
if (IsWriteDebugEnabled())
1306+
{
1307+
WriteWebResponseDebugInfo(response);
1308+
}
13171309
}
13181310
catch (TaskCanceledException ex)
13191311
{
@@ -1426,7 +1418,8 @@ internal virtual HttpResponseMessage GetResponse(HttpClient client, HttpRequestM
14261418
FillRequestStream(currentRequest);
14271419
}
14281420

1429-
totalRequests--;
1421+
// We know the message will usually be at least a certain size, so this reduces allocations.
1422+
StringBuilder verboseBuilder = new(128);
14301423
}
14311424
while (totalRequests > 0 && !response.IsSuccessStatusCode);
14321425

@@ -1437,13 +1430,181 @@ internal virtual void UpdateSession(HttpResponseMessage response)
14371430
{
14381431
ArgumentNullException.ThrowIfNull(response);
14391432
}
1440-
14411433
#endregion Virtual Methods
14421434

14431435
#region Helper Methods
14441436

14451437
internal static TimeSpan ConvertTimeoutSecondsToTimeSpan(int timeout) => timeout > 0 ? TimeSpan.FromSeconds(timeout) : Timeout.InfiniteTimeSpan;
14461438

1439+
private void WriteWebRequestVerboseInfo(HttpRequestMessage request)
1440+
{
1441+
try
1442+
{
1443+
// We know the message will usually be at least a certain size, so this reduces allocations.
1444+
StringBuilder verboseBuilder = new(128);
1445+
1446+
// "Redact" the query string from verbose output, the details will be visible in Debug output
1447+
string uriWithoutQuery = request.RequestUri.GetLeftPart(UriPartial.Path);
1448+
verboseBuilder.Append($"WebRequest: v{request.Version} {request.Method} {uriWithoutQuery}");
1449+
1450+
string requestContentType = ContentHelper.GetContentType(request);
1451+
if (requestContentType is not null)
1452+
{
1453+
verboseBuilder.Append($" with {requestContentType} payload");
1454+
}
1455+
1456+
long? requestContentLength = request.Content?.Headers?.ContentLength;
1457+
if (requestContentLength is not null)
1458+
{
1459+
verboseBuilder.Append($" ({ContentHelper.GetFriendlyContentLength(requestContentLength)})");
1460+
}
1461+
1462+
WriteVerbose(verboseBuilder.ToString().Trim());
1463+
}
1464+
catch (Exception ex)
1465+
{
1466+
// Just in case there are any edge cases we missed, we don't break workflows with an exception
1467+
WriteVerbose($"Failed to Write WebRequest Verbose Info: {ex} {ex.StackTrace}");
1468+
}
1469+
}
1470+
1471+
private void WriteWebRequestDebugInfo(HttpRequestMessage request)
1472+
{
1473+
try
1474+
{
1475+
// We know the message will usually be at least a certain size, so this reduces allocations.
1476+
StringBuilder debugBuilder = new("WebRequest Detail" + Environment.NewLine, 512);
1477+
1478+
if (!string.IsNullOrEmpty(request.RequestUri.Query))
1479+
{
1480+
debugBuilder.Append(DebugHeaderPrefix).AppendLine("QUERY");
1481+
string[] queryParams = request.RequestUri.Query.TrimStart('?').Split('&');
1482+
foreach (string param in queryParams)
1483+
{
1484+
debugBuilder.AppendLine(param);
1485+
}
1486+
}
1487+
1488+
debugBuilder.Append(DebugHeaderPrefix).AppendLine("HEADERS");
1489+
List<KeyValuePair<string, IEnumerable<string>>> allHeaders = new();
1490+
1491+
foreach (var headerSet in new HttpHeaders[] { request.Headers, request.Content?.Headers })
1492+
{
1493+
foreach (var header in headerSet)
1494+
{
1495+
debugBuilder
1496+
.Append($"{header.Key}: ")
1497+
.AppendJoin(", ", header.Value)
1498+
.AppendLine();
1499+
}
1500+
}
1501+
1502+
if (request.Content is not null)
1503+
{
1504+
debugBuilder
1505+
.AppendLine(DebugHeaderPrefix + "BODY")
1506+
.AppendLine(request.Content switch
1507+
{
1508+
StringContent stringContent => stringContent
1509+
.ReadAsStringAsync(_cancelToken.Token)
1510+
.GetAwaiter().GetResult(),
1511+
MultipartFormDataContent multipartContent => "=> Multipart Form Content"
1512+
+ Environment.NewLine
1513+
+ multipartContent.ReadAsStringAsync(_cancelToken.Token)
1514+
.GetAwaiter().GetResult(),
1515+
ByteArrayContent byteContent => InFile is not null
1516+
? "[Binary content: "
1517+
+ ContentHelper.GetFriendlyContentLength(byteContent.Headers.ContentLength)
1518+
+ "]"
1519+
: byteContent.ReadAsStringAsync(_cancelToken.Token).GetAwaiter().GetResult(),
1520+
StreamContent streamContent =>
1521+
"[Stream content: " + ContentHelper.GetFriendlyContentLength(streamContent.Headers.ContentLength) + "]",
1522+
_ => "[Unknown content type]",
1523+
});
1524+
}
1525+
1526+
WriteDebug(debugBuilder.ToString().Trim());
1527+
}
1528+
catch (Exception ex)
1529+
{
1530+
// Just in case there are any edge cases we missed, we don't break workflows with an exception
1531+
WriteVerbose($"Failed to Write WebRequest Debug Info: {ex} {ex.StackTrace}");
1532+
}
1533+
}
1534+
1535+
private void WriteWebResponseVerboseInfo(HttpResponseMessage response)
1536+
{
1537+
try
1538+
{
1539+
// We know the message will usually be at least a certain size, so this reduces allocations.
1540+
StringBuilder verboseBuilder = new(128);
1541+
verboseBuilder.Append($"WebResponse: {(int)response.StatusCode} {response.ReasonPhrase ?? response.StatusCode.ToString()}");
1542+
1543+
string responseContentType = ContentHelper.GetContentType(response);
1544+
if (responseContentType is not null)
1545+
{
1546+
verboseBuilder.Append($" with {responseContentType} payload");
1547+
}
1548+
1549+
long? responseContentLength = response.Content?.Headers?.ContentLength;
1550+
if (responseContentLength is not null)
1551+
{
1552+
verboseBuilder.Append($" ({ContentHelper.GetFriendlyContentLength(responseContentLength)})");
1553+
}
1554+
1555+
WriteVerbose(verboseBuilder.ToString().Trim());
1556+
}
1557+
catch (Exception ex)
1558+
{
1559+
// Just in case there are any edge cases we missed, we don't break workflows with an exception
1560+
WriteVerbose($"Failed to Write WebResponse Verbose Info: {ex} {ex.StackTrace}");
1561+
}
1562+
}
1563+
1564+
private void WriteWebResponseDebugInfo(HttpResponseMessage response)
1565+
{
1566+
try
1567+
{
1568+
// We know the message will usually be at least a certain size, so this reduces allocations.
1569+
StringBuilder debugBuilder = new("WebResponse Detail" + Environment.NewLine, 512);
1570+
1571+
debugBuilder.AppendLine(DebugHeaderPrefix + "HEADERS");
1572+
1573+
foreach (var headerSet in new HttpHeaders[] { response.Headers, response.Content?.Headers })
1574+
{
1575+
foreach (var header in headerSet)
1576+
{
1577+
debugBuilder.AppendLine($"{header.Key}: {string.Join(", ", header.Value)}");
1578+
}
1579+
}
1580+
1581+
if (response.Content is not null)
1582+
{
1583+
debugBuilder.AppendLine(DebugHeaderPrefix + "BODY");
1584+
1585+
if (ContentHelper.IsTextBasedContentType(ContentHelper.GetContentType(response)))
1586+
{
1587+
debugBuilder.AppendLine(
1588+
response.Content.ReadAsStringAsync(_cancelToken.Token)
1589+
.GetAwaiter().GetResult());
1590+
}
1591+
else
1592+
{
1593+
string friendlyContentLength = ContentHelper.GetFriendlyContentLength(
1594+
response.Content?.Headers?.ContentLength);
1595+
debugBuilder.AppendLine($"[Binary content: {friendlyContentLength}]");
1596+
}
1597+
}
1598+
1599+
WriteDebug(debugBuilder.ToString().Trim());
1600+
}
1601+
catch (Exception ex)
1602+
{
1603+
// Just in case there are any edge cases we missed, we don't break workflows with an exception
1604+
WriteVerbose($"Failed to Write WebResponse Debug Info: {ex} {ex.StackTrace}");
1605+
}
1606+
}
1607+
14471608
private Uri PrepareUri(Uri uri)
14481609
{
14491610
uri = CheckProtocol(uri);

‎src/Microsoft.PowerShell.Commands.Utility/resources/WebCmdletStrings.resx‎

Lines changed: 0 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -234,21 +234,9 @@
234234
<data name="FollowingRelLinkVerboseMsg" xml:space="preserve">
235235
<value>Following rel link {0}</value>
236236
</data>
237-
<data name="WebMethodInvocationVerboseMsg" xml:space="preserve">
238-
<value>Requested HTTP/{0} {1} with {2}-byte payload</value>
239-
</data>
240237
<data name="WebMethodResumeFailedVerboseMsg" xml:space="preserve">
241238
<value>The remote server indicated it could not resume downloading. The local file will be overwritten.</value>
242239
</data>
243-
<data name="WebResponseVerboseMsg" xml:space="preserve">
244-
<value>Received HTTP/{0} {1}-byte response of content type {2}</value>
245-
</data>
246-
<data name="WebRequestDebugMsg" xml:space="preserve">
247-
<value>Request {0}</value>
248-
</data>
249-
<data name="WebResponseDebugMsg" xml:space="preserve">
250-
<value>Response {0}</value>
251-
</data>
252240
<data name="WebResponseNoSizeVerboseMsg" xml:space="preserve">
253241
<value>Received HTTP/{0} response of content type {1} of unknown size</value>
254242
</data>

0 commit comments

Comments
 (0)