Tratcher
commented
9 months ago Turn the server logs all up to Debug level and see why the response is truncated.
Closed mu88 closed 9 months ago
Tratcher
commented
9 months ago Turn the server logs all up to Debug level and see why the response is truncated.
mu88
commented
9 months ago This is the updated logging config:
{
"Logging": {
"LogLevel": {
"Default": "Debug",
"Microsoft.AspNetCore": "Debug",
"Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware": "Debug"
}
}
}And this is the log output when running the app in Development mode for the request HTTP POST api/processor/process:
Tratcher
commented
9 months ago Huh, those error messages don't line up. The server says the client ended the connection before it finished sending the request body. The client says the server ended the connection before it finished sending the response. I suspect this is a client issue but we'll need wireshark traces to confirm. Connection level logs would also work. https://learn.microsoft.com/en-us/aspnet/core/fundamentals/servers/kestrel/connection-middleware?view=aspnetcore-8.0#connection-logging
Tratcher
commented
9 months ago @MihaZupan
mu88
commented
9 months ago I've added the following code to configure the connection logging:
builder.WebHost.ConfigureKestrel((_, serverOptions) =>
{
serverOptions.Listen(IPAddress.Any, 5254, listenOptions =>
{
listenOptions.UseConnectionLogging();
});
});And here's the output for HTTP POST api/processor/process via .PostAsJsonAsync:
And the output for the same request via .PostAsync (which succeeds):
One difference that I see (from a client-perspective) is that .PostAsJsonAsync chunks the request body whereas .PostAsync sends the complete request body at once.
mu88
commented
9 months ago And here another log for the statement await httpClient.PostAsync("internal-api/dataset/complete", new StringContent(string.Empty), CancellationToken.None) which succeeds on the server but throws the mentioned exception on the client:
Tratcher
commented
9 months ago Yup, there's a client bug here. It's posting as Chunked but not including any data, or even the chunked terminator. I do wonder if there an exception happening in the client, such as when serializing the content as json, and that causes it to abort sending.
Transferring to runtime.
ghost
commented
9 months ago Tagging subscribers to this area: @dotnet/ncl See info in area-owners.md if you want to be subscribed.
| Author: | mu88 |
|---|---|
| Assignees: | - |
| Labels: | `area-System.Net.Http` |
| Milestone: | - |
MihaZupan
commented
9 months ago I asked several colleagues to reproduce the issue with my repro case on their machines, but without luck: at the moment, I'm the only one with this problem.
This is suspicious and points at the issue being related to your environment (e.g. AV/software on the machine messing with the traffic).
For reference, I can't repro the issue either.
Can you collect a wireshark trace of the test, while also enabling debug logging in HttpClient? Modified sample with logging: https://gist.github.com/MihaZupan/331dddb261f8086b0dfc522901e221f6
ghost
commented
9 months ago This issue has been marked needs-author-action and may be missing some important information.
mu88
commented
9 months ago Can you collect a wireshark trace of the test, while also enabling debug logging in HttpClient?
As far as I understand, I need WinPcap for Wireshark to capture traffic from localhost to localhost. I spent several hours now, but unfortunately, I cannot make WinPcap work - Wireshark never shows the loopback interface 😑 maybe it is related to a company setting of my laptop, I've no idea.
Anyhow, please see the following debug log of the HttpClient.
ManickaP
commented
9 months ago The logged buffer looks correct:
0D0A
0D0A
3246 -- chunk size 2F (47)
0D0A
7B226A6F624964656E746966696572223A226D753838222C22636F6E6669726D4A6F625374617274223A747275657D -- chunk data {"jobIdentifier":"mu88","confirmJobStart":true}
0D0A
30 -- final chunk size 0
0D0A
0D0ACan you reproduce this on another machine? What about your coworkers, do they have the same problem? You can minimize the repro to simple console app and try it out on different machines/vms. But this does not look like HttpClient issue. From the logs, the data went out in correct form.
ghost
commented
9 months ago This issue has been marked needs-author-action and may be missing some important information.
mu88
commented
9 months ago Unfortunately, I'm the only one facing this issue. I already asked several colleagues to run my little repro suite and it succeeded for all of them.
ManickaP
commented
9 months ago So this is surely environmental and specific to your machine and your set up. I'd recommend trying to turn off one by one any and every program that might interfere with network traffic, e.g. antivirus, VPN, proxy etc., and see if anything helps. Otherwise, there isn't much we could help you with.
Tratcher
commented
9 months ago You can capture what the server received using server connection logging: https://learn.microsoft.com/en-us/aspnet/core/fundamentals/servers/kestrel/connection-middleware?view=aspnetcore-8.0#connection-logging
mu88
commented
9 months ago I was finally able to resolve the issue: I'm running an instance of px proxy on my machine and stopping it broke the whole test suite, which confused me. So I started removing the env vars http_proxy and https_proxy and out of a sudden, the tests were all green ✅
So I set the no_proxy env var to localhost, 127.0.0.1, started px proxy and the tests were still all green.
Long story short: px proxy resp. not configuring no_proxy was the problem.
Thank you very much for your help! I really appreciate it that you gave me your precious time 🙏🏻
Is there an existing issue for this?
Describe the bug
When running an HTTP POST or HTTP PUT request using the
HttpClientagainst an ASP.NET Core Web API, it fails with the following exception:This only happens under the following circumstances:
PutAsJsonAsyncis usedPostAsJsonAsyncis usedPostAsyncwithHttpContentofnullis usedPostAsyncwithHttpContentofnew StringContent(string.Empty)is usedThese requests only fail when using the
HttpClientin C#, but they succeed when running them via...Expected Behavior
The HTTP PUT and POST requests do not fail.
Steps To Reproduce
*.slnWebApiprojectIn my case, the test result looks like this:
When checking the
WebApilogs, I see that the backend seems to handle the requests properly - at least I always see a2xxstatus code:ASP.NET Core Logs (details dropdown)
``` info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /api/processor/process Host: localhost:5254 Content-Type: application/json; charset=utf-8 Content-Length: 50 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: PUT Scheme: http PathBase: Path: /api/processor/process Host: localhost:5254 Content-Type: application/json; charset=utf-8 Content-Length: 50 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: GET Scheme: http PathBase: Path: /api/processor/hello Host: localhost:5254 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 200 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: DELETE Scheme: http PathBase: Path: /api/processor/goodbye Host: localhost:5254 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 200 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /internal-api/dataset/complete Host: localhost:5254 Content-Length: 0 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /internal-api/dataset/complete Host: localhost:5254 Content-Length: 0 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /internal-api/dataset/complete Host: localhost:5254 Content-Length: 0 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /internal-api/dataset/complete Host: localhost:5254 Content-Length: 0 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /internal-api/dataset/complete Host: localhost:5254 Content-Type: text/plain; charset=utf-8 Content-Length: 0 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 204 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: PUT Scheme: http PathBase: Path: /api/processor/process Host: localhost:5254 Content-Type: application/json; charset=utf-8 Transfer-Encoding: chunked info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1] Request: Protocol: HTTP/1.1 Method: POST Scheme: http PathBase: Path: /api/processor/process Host: localhost:5254 Content-Type: application/json; charset=utf-8 Transfer-Encoding: chunked info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 200 info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2] Response: StatusCode: 200 ```The tests are only used for easier usage. Instead, the CLI project
Clientcan be used as well and triggers the same exceptions.Exceptions (if any)
.NET Version
8.0.101
Anything else?
Additional information
dotnet --info:Dotnet info
``` .NET SDK: Version: 8.0.101 Commit: 6eceda187b Workload version: 8.0.100-manifests.f64b8c85 Runtime Environment: OS Name: Windows OS Version: 10.0.19045 OS Platform: Windows RID: win-x64 Base Path: C:\Program Files\dotnet\sdk\8.0.101\ .NET workloads installed: Workload version: 8.0.100-manifests.f64b8c85 [maui-maccatalyst] Installation Source: SDK 8.0.100 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: Msi [maui-tizen] Installation Source: SDK 8.0.100 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: Msi [maui-windows] Installation Source: VS 17.8.34408.163 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: Msi [maccatalyst] Installation Source: VS 17.8.34408.163 Manifest Version: 17.0.8490/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maccatalyst\17.0.8490\WorkloadManifest.json Install Type: Msi [ios] Installation Source: VS 17.8.34408.163 Manifest Version: 17.0.8490/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.ios\17.0.8490\WorkloadManifest.json Install Type: Msi [android] Installation Source: VS 17.8.34408.163 Manifest Version: 34.0.52/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.android\34.0.52\WorkloadManifest.json Install Type: Msi Host: Version: 8.0.1 Architecture: x64 Commit: bf5e279d92 .NET SDKs installed: 2.1.700 [C:\Program Files\dotnet\sdk] 2.2.300 [C:\Program Files\dotnet\sdk] 8.0.101 [C:\Program Files\dotnet\sdk] .NET runtimes installed: Microsoft.AspNetCore.All 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All] Microsoft.AspNetCore.All 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All] Microsoft.AspNetCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.15 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 8.0.1 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Other architectures found: x86 [C:\Program Files (x86)\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation] Environment variables: Not set global.json file: Not found ```Directory.Build.props) - the exception stays the same.Broader context
Of course, this is a rather simplified example. In our team, we're maintaining a dozen of different apps following the same pattern which is similar to the shown example. Since we set great store by testing, we have a lot of system integration tests where we test our ASP.NET Core Web API (which is running in Docker) via
HttpClient.Since I got a new laptop, I installed all the necessary pieces (Git, .NET SDK, Docker Desktop, etc.) and cloned several of our apps. I can run all unit and integration tests, but some of the system integration tests fail. It took me a long time to remove the complexity step by step until I noticed that only those tests fail which make use HTTP POST or PUT using the
HttpClient. So I further removed different layers (Docker, xUnit) and reduced it down to a dumb CLI app using theHttpClientto access an ASP.NET Core Web API - the result is the repro repo https://github.com/mu88/Repro_HttpClient_POST_fails.❗ So at the moment, I'm not able to run any of our system integration tests that make use of HTTP POST or PUT. Therefore, this bug has a certain impact on my inner dev loop and I'd appreciate it if you could have a look.
I'm fully aware that you (as my colleagues) probably won't be able to reproduce the problem. However, I hope that you can give me some guidance on what to analyze. Thanks in advance!