[dotnet] Log http requests/responses via internal DiagnosticsHttpHandler

[ChrstnAnsl]

User description

Description

Added Context to support and fix BUG #13920

Motivation and Context

I have encountered the same issue and wanting to debug it more but unfortunately there's not enough error logs to let me debug it

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to change)

Checklist

• I have read the contributing document.
• My change requires a change to the documentation.
• I have updated the documentation accordingly.
• I have added tests to cover my changes.
• All new and existing tests passed.

---

PR Type

Bug fix, Enhancement

---

Description

• Added detailed logging for HTTP request and response bodies in HttpCommandExecutor.
• Enhanced trace logging to include the content of HTTP requests and responses.
• Aimed to improve debugging capabilities by providing more comprehensive error logs.

---

Changes walkthrough 📝

	Relevant files
Enhancement	HttpCommandExecutor.cs Add detailed logging for HTTP request and response bodies dotnet/src/webdriver/Remote/HttpCommandExecutor.cs Added logging for request and response bodies. Enhanced trace logging to include request and response content. +8/-0

---

💡 PR-Agent usage:
Comment /help on the PR to get a list of all available PR-Agent tools and their descriptions

[CLAassistant]

All committers have signed the CLA.

[qodo-merge-pro]

PR Description updated to latest commit (a6c82f6)

• Copy walkthrough table to "Files Changed" Tab

[qodo-merge-pro]

PR Review 🔍

⏱️ Estimated effort to review [1-5]	2, because the changes are localized to a single file and involve adding logging functionality which is straightforward. The logic is not complex, and the changes are well-contained.
🧪 Relevant tests	No
⚡ Possible issues	Performance Concern: The addition of logging for HTTP request and response bodies could potentially lead to performance degradation, especially if the content size is large. This might slow down the execution context significantly.
	Sensitive Data Exposure: Logging HTTP response and request bodies might inadvertently expose sensitive data in the logs, which could be a security risk if logs are not properly secured or if sensitive data is not adequately masked.
🔒 Security concerns	Sensitive Data Exposure: The new logging functionality could potentially expose sensitive information contained in HTTP requests or responses if not properly handled. This includes personal data, authentication tokens, or other sensitive information that might be part of the HTTP body.

[qodo-merge-pro]

PR Code Suggestions ✨

Category	Suggestion	Score
Possible bug	✅ Add a null check for responseMessage.Content before reading the response body Suggestion Impact: The suggestion was implemented by adding a null check for responseMessage.Content before attempting to read the response body and logging it. code diff: - if (_logger.IsEnabled(LogEventLevel.Trace)) - { - _logger.Trace($"<< {responseMessage}"); - string responseBody = await responseMessage.Content.ReadAsStringAsync(); - _logger.Trace($"<< Body: {responseBody}"); Consider adding a null check for responseMessage.Content before attempting to read the response body to avoid potential NullReferenceException. dotnet/src/webdriver/Remote/HttpCommandExecutor.cs [301-302] -string responseBody = await responseMessage.Content.ReadAsStringAsync(); -_logger.Trace($"&lt;&lt; Body: {responseBody}"); +if (responseMessage.Content != null) +{ + string responseBody = await responseMessage.Content.ReadAsStringAsync(); + _logger.Trace($"&lt;&lt; Body: {responseBody}"); +} Suggestion importance[1-10]: 10 Why: This suggestion correctly identifies a potential NullReferenceException by adding a null check before accessing responseMessage.Content, which is crucial for robustness.	10
Performance	✅ Use ConfigureAwait(false) when awaiting ReadAsStringAsync calls to avoid potential performance issues Suggestion Impact: The suggestion to use ConfigureAwait(false) when awaiting ReadAsStringAsync calls was implemented in multiple places in the commit. code diff: + responseInfo = await this.MakeHttpRequest(requestInfo).ConfigureAwait(false); } catch (HttpRequestException ex) { @@ -237,7 +247,14 @@ httpClientHandler.Proxy = this.Proxy; - this.client = new HttpClient(httpClientHandler); + HttpMessageHandler handler = httpClientHandler; + + if (_logger.IsEnabled(LogEventLevel.Trace)) + { + handler = new DiagnosticsHttpHandler(httpClientHandler, _logger); + } + + this.client = new HttpClient(handler); this.client.DefaultRequestHeaders.UserAgent.ParseAdd(this.UserAgent); this.client.DefaultRequestHeaders.Accept.ParseAdd(RequestAcceptHeader); this.client.DefaultRequestHeaders.ExpectContinue = false; @@ -283,25 +300,8 @@ requestMessage.Content.Headers.ContentType = contentTypeHeader; } - if (_logger.IsEnabled(LogEventLevel.Trace)) - { - _logger.Trace($">> {requestMessage}"); - if (requestMessage.Content != null) - { - string content = await requestMessage.Content.ReadAsStringAsync(); - _logger.Trace($">> Body: {content}"); - } - } - using (HttpResponseMessage responseMessage = await this.client.SendAsync(requestMessage).ConfigureAwait(false)) { - if (_logger.IsEnabled(LogEventLevel.Trace)) - { - _logger.Trace($"<< {responseMessage}"); - string responseBody = await responseMessage.Content.ReadAsStringAsync(); - _logger.Trace($"<< Body: {responseBody}"); - } - HttpResponseInfo httpResponseInfo = new HttpResponseInfo(); httpResponseInfo.Body = await responseMessage.Content.ReadAsStringAsync().ConfigureAwait(false); httpResponseInfo.ContentType = responseMessage.Content.Headers.ContentType?.ToString(); @@ -312,7 +312,6 @@ } } - private Response CreateResponse(HttpResponseInfo responseInfo) { Response response = new Response(); @@ -393,5 +392,56 @@ public string Body { get; set; } public string ContentType { get; set; } } + + /// <summary> + /// Internal diagnostic handler to log http requests/responses. + /// </summary> + private class DiagnosticsHttpHandler : DelegatingHandler + { + private readonly ILogger _logger; + + public DiagnosticsHttpHandler(HttpMessageHandler messageHandler, ILogger logger) + : base(messageHandler) + { + _logger = logger; + } + + /// <summary> + /// Sends the specified request and returns the associated response. + /// </summary> + /// <param name="request">The request to be sent.</param> + /// <param name="cancellationToken">A CancellationToken object to allow for cancellation of the request.</param> + /// <returns>The http response message content.</returns> + protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + StringBuilder requestLogMessageBuilder = new(); + requestLogMessageBuilder.AppendFormat(">> {0}", request); + + if (request.Content != null) + { + var requestContent = await request.Content.ReadAsStringAsync().ConfigureAwait(false); + requestLogMessageBuilder.AppendFormat("{0}{1}", Environment.NewLine, requestContent); + } + + var responseTask = base.SendAsync(request, cancellationToken).ConfigureAwait(false); + + _logger.Trace(requestLogMessageBuilder.ToString()); + + var response = await responseTask; + + StringBuilder responseLogMessageBuilder = new(); + responseLogMessageBuilder.AppendFormat("<< {0}", response); + + if (!response.IsSuccessStatusCode && response.Content != null) + { + var responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false); + responseLogMessageBuilder.AppendFormat("{0}{1}", Environment.NewLine, responseContent); + } + + _logger.Trace(responseLogMessageBuilder.ToString()); To avoid potential performance issues, consider using ConfigureAwait(false) when awaiting ReadAsStringAsync calls. dotnet/src/webdriver/Remote/HttpCommandExecutor.cs [291-292] -string content = await requestMessage.Content.ReadAsStringAsync(); +string content = await requestMessage.Content.ReadAsStringAsync().ConfigureAwait(false); _logger.Trace($"&gt;&gt; Body: {content}"); Suggestion importance[1-10]: 8 Why: Using ConfigureAwait(false) is important in this context to prevent deadlocks and improve performance in asynchronous code. The suggestion is correct and targets the new code in the PR.	8
Maintainability	✅ Extract the logging logic into a separate method for better readability and maintainability Suggestion Impact: The logging logic for HTTP requests and responses was extracted into a separate method within a new DiagnosticsHttpHandler class, improving readability and maintainability. code diff: + /// <summary> + /// Internal diagnostic handler to log http requests/responses. + /// </summary> + private class DiagnosticsHttpHandler : DelegatingHandler + { + private readonly ILogger _logger; + + public DiagnosticsHttpHandler(HttpMessageHandler messageHandler, ILogger logger) + : base(messageHandler) + { + _logger = logger; + } + + /// <summary> + /// Sends the specified request and returns the associated response. + /// </summary> + /// <param name="request">The request to be sent.</param> + /// <param name="cancellationToken">A CancellationToken object to allow for cancellation of the request.</param> + /// <returns>The http response message content.</returns> + protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + StringBuilder requestLogMessageBuilder = new(); + requestLogMessageBuilder.AppendFormat(">> {0}", request); + + if (request.Content != null) + { + var requestContent = await request.Content.ReadAsStringAsync().ConfigureAwait(false); + requestLogMessageBuilder.AppendFormat("{0}{1}", Environment.NewLine, requestContent); + } + + var responseTask = base.SendAsync(request, cancellationToken).ConfigureAwait(false); + + _logger.Trace(requestLogMessageBuilder.ToString()); + + var response = await responseTask; + + StringBuilder responseLogMessageBuilder = new(); + responseLogMessageBuilder.AppendFormat("<< {0}", response); + + if (!response.IsSuccessStatusCode && response.Content != null) + { + var responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false); + responseLogMessageBuilder.AppendFormat("{0}{1}", Environment.NewLine, responseContent); + } + + _logger.Trace(responseLogMessageBuilder.ToString()); + + return response; + } + } To improve readability and maintainability, consider extracting the logging logic into a separate method. dotnet/src/webdriver/Remote/HttpCommandExecutor.cs [286-294] -if (_logger.IsEnabled(LogEventLevel.Trace)) +LogRequestMessage(requestMessage); + +private async Task LogRequestMessage(HttpRequestMessage requestMessage) { - _logger.Trace($"&gt;&gt; {requestMessage}"); - if (requestMessage.Content != null) + if (_logger.IsEnabled(LogEventLevel.Trace)) { - string content = await requestMessage.Content.ReadAsStringAsync(); - _logger.Trace($"&gt;&gt; Body: {content}"); + _logger.Trace($"&gt;&gt; {requestMessage}"); + if (requestMessage.Content != null) + { + string content = await requestMessage.Content.ReadAsStringAsync(); + _logger.Trace($"&gt;&gt; Body: {content}"); + } } } Suggestion importance[1-10]: 7 Why: Extracting the logging logic into a separate method improves readability and maintainability, but it is not a critical change. The suggestion correctly identifies the relevant code block.	7
Best practice	✅ Remove the unnecessary blank line at the end of the method Suggestion Impact: The unnecessary blank line at the end of the method was removed, keeping the code clean and consistent. code diff: - private Response CreateResponse(HttpResponseInfo responseInfo) Remove the unnecessary blank line at the end of the method to keep the code clean and consistent. dotnet/src/webdriver/Remote/HttpCommandExecutor.cs [314-315] } - private Response CreateResponse(HttpResponseInfo responseInfo) Suggestion importance[1-10]: 4 Why: While removing unnecessary blank lines can improve code cleanliness, it is a minor stylistic improvement and not crucial to the functionality or readability of the code.	4

[nvborisenko]

@SeleniumHQ/selenium-committers should we include http request/response body of internal wire protocol to internal logs?

[ChrstnAnsl]

@SeleniumHQ/selenium-committers should we include http request/response body of internal wire protocol to internal logs?

Hi @nvborisenko I'll wait for everyone's opinion on whether we should include HTTP request/response bodies in internal logs. Let's gather everyone's thoughts about this then later on we can decide whether to include it or not. Thanks for looking up

[pujagani]

Hey! Thank you for your contribution. However, a typical concern with logging HTTP responses is the body size. For example, the response size might be huge when fetching the web page source. It might be a good idea to log the HTTP response body if the status code is not 2xx. Basically, logging in detail on error situations only.

[ChrstnAnsl]

Hey! Thank you for your contribution. However, a typical concern with logging HTTP responses is the body size. For example, the response size might be huge when fetching the web page source. It might be a good idea to log the HTTP response body if the status code is not 2xx. Basically, logging in detail on error situations only.

That's a great valid point. I will take it into consideration and update the PR accordingly. Thanks @pujagani

[ChrstnAnsl]

Hey! Thank you for your contribution. However, a typical concern with logging HTTP responses is the body size. For example, the response size might be huge when fetching the web page source. It might be a good idea to log the HTTP response body if the status code is not 2xx. Basically, logging in detail on error situations only.

That's a great valid point. I will take it into consideration and update the PR accordingly. Thanks @pujagani

Hey! Thank you for your contribution. However, a typical concern with logging HTTP responses is the body size. For example, the response size might be huge when fetching the web page source. It might be a good idea to log the HTTP response body if the status code is not 2xx. Basically, logging in detail on error situations only.

Hi @pujagani updated the PR. Please see the changes. Thank you!

[pujagani]

LGTM. Thank you! @nvborisenko is the C# expert. Please help review it further.

[ChrstnAnsl]

@nvborisenko Fix and consider all the suggestions and comments.

Please see the latest commit

[nvborisenko]

@ChrstnAnsl this is exactly what we wanted to see and can accept, thank you! Please just fix minor issues.

BTW do you want to improve the logic here little bit? Now in logs we will see 2 log entries for http request: the first one is like >> POST to https://url ... and the second one is request body content. What if we can merge it and put http request details as a single log entry like:

POST to https://url ...
{
  ...
}

where { ... } is request body content.

[ChrstnAnsl]

Hi @nvborisenko adjusted the logic and fix the last minor comment. Please see the latest commit. Thank you

[nvborisenko]

Let me help here slightly, I am going to push new commits if you don't mind.

[ChrstnAnsl]

Sure, go ahead! Thanks

[nvborisenko]

I am done, could you please review?

[ChrstnAnsl]

Hi @nvborisenko LGTM!

[nvborisenko]

In logs we see:

10:36:40.134 TRACE HttpCommandExecutor: >> Method: POST, RequestUri: 'http://localhost:37361/session/e44b09c547486f5ea4c198895969e659/url', Version: 1.1, Content: System.Net.Http.ByteArrayContent, Headers:
{
  Accept: application/json; charset=utf-8
  User-Agent: selenium/4.23.0-nightly202406201609
  User-Agent: (.net linux)
  Content-Type: application/json; charset=utf-8
}
{"url":"http://localhost:43323/common/temp/page7006338836466627400.html"}
10:36:40.197 TRACE HttpCommandExecutor: << StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Cache-Control: no-cache
  Content-Length: 14
  Content-Type: application/json; charset=utf-8
}

Looks good to me.