LoggingHttpMessageHandler should log unescaped URL in log message

[antmeehan]

Description

The built-in logging provided for HttpClient by LoggingHttpMessageHandler displays the URLs using Uri.ToString(). This means that they are shown in the unencoded format, different to what is actually requested on the network.

I think this can cause some confusion (it did for me), since it isn't clear what exactly is being requested. I think using Uri.AbsoluteUri would be more accurate.

Reproduction Steps

public class LoggerTests
{
    private readonly ITestOutputHelper _outputHelper;

    public LoggerTests(ITestOutputHelper outputHelper)
    {
        _outputHelper = outputHelper;
    }
    [Fact]
    public async Task Test1()
    {
        var services = new ServiceCollection()
            .AddLogging(builder => builder.AddXUnit(_outputHelper))
            .AddHttpClient();
        
        var client = services.BuildServiceProvider().GetRequiredService<HttpClient>();
        await client.GetAsync("http://www.tired.com/a=here%20I%20am");
    }
}

Expected behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Actual behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Regression?

No response

Known Workarounds

No response

Configuration

• .NET 6
• Windows
• x64

Other information

No response

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

The built-in logging provided for HttpClient by LoggingHttpMessageHandler displays the URLs using Uri.ToString(). This means that they are shown in the unencoded format, different to what is actually requested on the network.

I think this can cause some confusion (it did for me), since it isn't clear what exactly is being requested. I think using Uri.AbsoluteUri would be more accurate.

Reproduction Steps

public class LoggerTests
{
    private readonly ITestOutputHelper _outputHelper;

    public LoggerTests(ITestOutputHelper outputHelper)
    {
        _outputHelper = outputHelper;
    }
    [Fact]
    public async Task Test1()
    {
        var services = new ServiceCollection()
            .AddLogging(builder => builder.AddXUnit(_outputHelper))
            .AddHttpClient();
        
        var client = services.BuildServiceProvider().GetRequiredService<HttpClient>();
        await client.GetAsync("http://www.tired.com/a=here%20I%20am");
    }
}

Expected behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Actual behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Regression?

No response

Known Workarounds

No response

Configuration

• .NET 6
• Windows
• x64

Other information

No response

Author:	antmeehan
Assignees:	-
Labels:	area-System.Net.Http, untriaged
Milestone:	-

[karelz]

Sounds reasonable to me. @MihaZupan any thoughts?

[MihaZupan]

I agree, ToString is not appropriate. Either we should log the IdnHost & PathAndQuery or the AbsoluteUri.

[karelz]

The code live here: https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs
@ericstj how is that tracked? Is it now owned by BCL team?

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

The built-in logging provided for HttpClient by LoggingHttpMessageHandler displays the URLs using Uri.ToString(). This means that they are shown in the unencoded format, different to what is actually requested on the network.

I think this can cause some confusion (it did for me), since it isn't clear what exactly is being requested. I think using Uri.AbsoluteUri would be more accurate.

Reproduction Steps

public class LoggerTests
{
    private readonly ITestOutputHelper _outputHelper;

    public LoggerTests(ITestOutputHelper outputHelper)
    {
        _outputHelper = outputHelper;
    }
    [Fact]
    public async Task Test1()
    {
        var services = new ServiceCollection()
            .AddLogging(builder => builder.AddXUnit(_outputHelper))
            .AddHttpClient();
        
        var client = services.BuildServiceProvider().GetRequiredService<HttpClient>();
        await client.GetAsync("http://www.tired.com/a=here%20I%20am");
    }
}

Expected behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here%20I%20am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Actual behavior

[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:21Z] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET http://www.tired.com/a=here I am
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 666.6251ms - 404
[2021-12-16 07:31:22Z] info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 685.3155ms - 404

Regression?

No response

Known Workarounds

No response

Configuration

• .NET 6
• Windows
• x64

Other information

No response

Author:	antmeehan
Assignees:	-
Labels:	untriaged, area-Extensions-HttpClientFactory
Milestone:	-

[ericstj]

Yes, this is HttpClientFactory. I've updated the area label appropriately. I believe the request applies to changing:

runtime/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs

Line 100 in 5abee29

"Start processing HTTP request {HttpMethod} {Uri}");

runtime/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs

Line 96 in 1a83f61

"Sending HTTP request {HttpMethod} {Uri}");

[antmeehan]

I've had a go at the fix for main #63012.