runtime: System.Net.Http.HttpClient always fails on first attempted connection

Description

On the first attempt to connect to a web site, the connection always fails with a “Received an unexpected EOF or 0 bytes from the transport stream.” exception. On the second and subsequent attempts it works as expected.

This was first apparent to me because the behavior appeared suddenly in PowerShell 7.2.x+. A simple Invoke-WebRequest fails the first time, then works fine for the rest of the session. Meanwhile, PowerShell 5 works as expected on the same platform.

Discussion over in the PowerShell repo in topic 20813 led to trying a purely C# code test (below) that suggests this is not a PowerShell issue, but some weird edge case that is surfaced in .NET

I can reproduce the behavior on multiple systems in my organization, on the LAN or not, even completely disconnected from the network using a loopback web server. I can also reproduce it under Windows Subsystem for Linux (kali) using Mono (6.8.0.105).

Reproduction Steps

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Net.Http;
using System.Net;


namespace HTTP_Test
{
    class program
    {
        static void Main()
        {
            Task t = new Task(HTTP_GET);
            t.Start();
            Console.ReadLine();
        }

        static async void HTTP_GET()
        {
            var TARGETURL = "https://www.google.com/";

            HttpClientHandler handler = new HttpClientHandler();

            Console.WriteLine("GET: + " + TARGETURL);

            // ... Use HttpClient.
            HttpClient client = new HttpClient(handler);

            HttpResponseMessage response = await client.GetAsync(TARGETURL);
            HttpContent content = response.Content;

            // ... Check Status Code
            Console.WriteLine("Response StatusCode: " + (int)response.StatusCode);

        }
    }
}

Expected behavior

Network connection should work the first time.

Actual behavior

Connection fails on first attempt every time.

Regression?

No response

Known Workarounds

Use PowerShell 5.

Configuration

My system is .NET release 533325, Windows 10 22H2 (19045.3570) on an x64.

Has been reproduced on multiple versions of Windows 10 on various hardware platforms, including a VDI. This has also been reproduced under Windows Subsystem for Linux on my laptop.

Other information

No response

About this issue

  • Original URL
  • State: open
  • Created 7 months ago
  • Comments: 28 (17 by maintainers)

Most upvoted comments

TL;DR: Here’s a modified test case based on yours, please run it (verify that the issue happens) and share the output with us. HttpTest-5.0-p8.zip

Hi @mkellen1, sorry for the delay. Can I please ask you to also collect the extended telemetry while the issue happens? It is very strange that there are no packages for the first connection attempt, but we should at least see it in the telemetry.

Official docs for networking telemetry are here, but we also need internal diagnostic event sources which are not listed on this page; also, as a funny coincidence, the names of these internal event sources changed right between 5.0-p8 and 5.0-rc1 😄 (https://github.com/dotnet/runtime/commit/ba7c518a494ef7aa87159816e07576eefe14290f) – so I went ahead and wrote for you an event listener class to collect everything:

NetEventListener
    public sealed class NetEventListener : EventListener
    {
        public static string[] NetworkingEvents => new[]
        {
            "System.Net.Http",
            "System.Net.NameResolution",
            "System.Net.Sockets",
            "System.Net.Security",
            // internal telemetry names from 5.0 rc1
            "Private.InternalDiagnostics.System.Net.Http",
            "Private.InternalDiagnostics.System.Net.NameResolution",
            "Private.InternalDiagnostics.System.Net.Sockets",
            "Private.InternalDiagnostics.System.Net.Security",
            "Private.InternalDiagnostics.System.Net.NetworkInformation",
            "Private.InternalDiagnostics.System.Net.Primitives",
            // internal telemetry names prior to 5.0 rc1
            "Microsoft-System-Net-Http",
            "Microsoft-System-Net-NameResolution",
            "Microsoft-System-Net-Sockets",
            "Microsoft-System-Net-Security",
            "Microsoft-System-Net-NetworkInformation",
            "Microsoft-System-Net-Primitives",
        };

        private readonly HashSet<string> _sourceNames;
        private List<EventSource> _eventSources = new List<EventSource>();
        public NetEventListener()
        {
            lock (this)
            {
                _sourceNames = new HashSet<string>(NetworkingEvents);
                foreach (EventSource eventSource in _eventSources)
                {
                    OnEventSourceCreated(eventSource);
                }
                _eventSources = null!;
            }
        }

        protected override void OnEventSourceCreated(EventSource eventSource)
        {
            lock (this)
            {
                // We're called from base ctor, just save the event source for later initialization.
                if (_sourceNames is null)
                {
                    _eventSources.Add(eventSource);
                    return;
                }

                // Second pass called from our ctor, allow logging for specified source names.
                if (_sourceNames.Contains(eventSource.Name))
                {
                    EnableEvents(eventSource, EventLevel.LogAlways);
                }
            }
        }

        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {
            StringBuilder sb = new StringBuilder().
                Append($"{eventData.TimeStamp:HH:mm:ss.fffffff}[{eventData.EventName}] ");

            for (int i = 0; i < eventData.Payload?.Count; i++)
            {
                if (i > 0)
                    sb.Append(", ");
                sb.Append(eventData.PayloadNames?[i]).Append(": ").Append(eventData.Payload[i]);
            }
            try
            {
                Console.WriteLine(sb.ToString());
            }
            catch { }
        }
    }

Then you need to create an instance at the start of your test app. Here’s the modified test loosely based on what you’ve sent above:

Program
    class Program
    {
        static async Task Main(string[] args)
        {
            var listener = new NetEventListener();

            Console.WriteLine(RuntimeInformation.FrameworkDescription);
            var url = "http://localhost/";

            var client = new HttpClient();
            
            Console.WriteLine("\n#1");
            await TestGetAsync(client, url);

            Console.WriteLine("\n#2");
            await TestGetAsync(client, url);
        }

        private static async Task TestGetAsync(HttpClient client, string url)
        {
            Console.WriteLine($"GET {url}\n");
            var response = await client.GetAsync(url);
            Console.WriteLine($"\n{(int)response.StatusCode} {response.StatusCode}");
            Console.WriteLine(await response.Content.ReadAsStringAsync());
        }
    }

As a reference, this is my output from it:

5.0 Preview 8
➜ HttpTest-5.0-p8  dotnet run -c release
.NET 5.0.0-preview.8.20407.11
22:42:52.8397503[Info] thisOrContextObject: HttpClientHandler#32854180, memberName: .ctor, message: 
22:42:52.8480122[Info] thisOrContextObject: SocketsHttpHandler#27252167, memberName: .ctor, message: 
22:42:52.8481729[Info] thisOrContextObject: DiagnosticsHandler#43942917, memberName: .ctor, message: 
22:42:52.8483628[Associate] thisOrContextObject: DiagnosticsHandler#43942917, memberName: InnerHandler, first: DiagnosticsHandler#43942917, second: SocketsHttpHandler#27252167
22:42:52.8501734[Associate] thisOrContextObject: HttpClient#59941933, memberName: .ctor, first: HttpClient#59941933, second: HttpClientHandler#32854180

#1
GET http://localhost/

22:42:52.8892802[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: .ctor, message: AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null)
22:42:52.8894258[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: .ctor, message: _useProxy=True
22:42:52.8895426[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: TryCreate, message: AutoSettingsUsed, calling WinHttpOpen
22:42:52.8960012[Info] thisOrContextObject: HttpConnectionHandler#23458411, memberName: .ctor, message: 
22:42:52.8961003[Info] thisOrContextObject: RedirectHandler#9799115, memberName: .ctor, message: 
22:42:52.8977850[RequestStart] scheme: http, host: localhost, port: 80, pathAndQuery: /, versionMajor: 1, versionMinor: 1
22:42:52.9006364[ErrorMessage] thisOrContextObject: WinInetProxyHelper#2606490, memberName: GetProxyForUrl, message: error=12180
22:42:52.9008192[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: GetProxyForUrl, message: useProxy=False
22:42:52.9029805[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: .ctor, message: HttpConnectionPool http://localhost:80
22:42:52.9059360[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: IncrementConnectionCountNoLock, message: 
22:42:52.9061533[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: GetHttpConnectionAsync, message: Creating new connection for pool.
22:42:52.9108481[Info] thisOrContextObject: ConnectEventArgs#55530882, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#30015890
22:42:52.9179918[Info] thisOrContextObject: (null), memberName: GetHostName, message: knatalia-P53
22:42:52.9207439[Info] thisOrContextObject: Socket#1707556, memberName: .ctor, message: InterNetwork
22:42:52.9213164[Info] thisOrContextObject: (null), memberName: CreateSocket, message: SafeSocketHandle:15368010(0x524)
22:42:52.9214536[Info] thisOrContextObject: Socket#4094363, memberName: .ctor, message: InterNetworkV6
22:42:52.9216312[Info] thisOrContextObject: (null), memberName: CreateSocket, message: SafeSocketHandle:36849274(0x528)
22:42:52.9317561[Info] thisOrContextObject: SocketAsyncEventArgs#6044116, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#59817589
22:42:52.9323020[Info] thisOrContextObject: Socket#4094363, memberName: WildcardBindForConnectIfNecessary, message: ::
22:42:52.9328131[ConnectStart] address: InterNetworkV6:28:{0,80,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0,0,0,0}
22:42:52.9333013[Info] thisOrContextObject: SafeSocketHandle#36849274, memberName: GetOrAllocateThreadPoolBoundHandle, message: calling ThreadPool.BindHandle()
22:42:52.9390887[Connected] localEp: IPEndPoint#-508592849, remoteEp: (null), socketHash: 4094363
22:42:52.9393856[ConnectStop]
22:42:52.9396242[Info] thisOrContextObject: Socket#4094363, memberName: SetToConnected, message: now connected
22:42:52.9399142[Info] thisOrContextObject: Socket#1707556, memberName: Connected, message: _isConnected:False
22:42:52.9400941[Info] thisOrContextObject: Socket#1707556, memberName: Dispose, message: timeout = -1
22:42:52.9403678[Info] thisOrContextObject: Socket#1707556, memberName: Dispose, message: disposing:True Disposed:False
22:42:52.9406386[Info] thisOrContextObject: Socket#1707556, memberName: Dispose, message: Calling _handle.CloseAsIs()
22:42:52.9408244[Info] thisOrContextObject: SafeSocketHandle#15368010, memberName: CloseAsIs, message: shouldClose=True
22:42:52.9410259[Info] thisOrContextObject: SafeSocketHandle#15368010, memberName: ReleaseHandle, message: shouldClose=False
22:42:52.9411965[Info] thisOrContextObject: SafeSocketHandle#15368010, memberName: CloseHandle, message: handle:0x524
22:42:52.9414273[Info] thisOrContextObject: SafeSocketHandle#15368010, memberName: DoCloseHandle, message: handle:0x524, Following 'blockable' branch
22:42:52.9416980[Info] thisOrContextObject: SafeSocketHandle#15368010, memberName: DoCloseHandle, message: handle:0x524, closesocket()#1:Success
22:42:52.9422218[Info] thisOrContextObject: Socket#4094363, memberName: Connected, message: _isConnected:True
22:42:52.9430180[Info] thisOrContextObject: Socket#4094363, memberName: SetSocketOption, message: optionLevel:Tcp optionName:NoDelay optionValue:1
22:42:52.9436246[Info] thisOrContextObject: Socket#4094363, memberName: SetSocketOption, message: SetSockOpt returns errorCode:Success
22:42:52.9438701[Info] thisOrContextObject: Socket#4094363, memberName: Connected, message: _isConnected:True
22:42:52.9456343[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: TraceConnection, message: HttpConnection(HttpConnectionPool http://localhost:80)
22:42:52.9486705[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Sending request: Method: GET, RequestUri: 'http://localhost/', Version: 1.1, Content: <null>, Headers:
{
}
22:42:52.9506580[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: WriteToStreamAsync, message: Writing 35 bytes.
22:42:52.9509645[Info] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#31364015
22:42:52.9521955[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: LogBuffer, buffer: System.Byte[]
22:42:52.9525945[Associate] thisOrContextObject: HttpResponseMessage#28379535, memberName: RequestMessage, first: HttpResponseMessage#28379535, second: HttpRequestMessage#11429296
22:42:52.9528216[Info] thisOrContextObject: HttpConnectionResponseContent#64109423, memberName: .ctor, message:
22:42:52.9530812[Associate] thisOrContextObject: HttpResponseMessage#28379535, memberName: Content, first: HttpResponseMessage#28379535, second: HttpConnectionResponseContent#64109423
22:42:52.9541727[Info] thisOrContextObject: AwaitableSocketAsyncEventArgs#35236192, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#21943666
22:42:52.9547879[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#35236192, memberName: LogBuffer, buffer: System.Byte[]
22:42:52.9550743[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: FillAsync, message: Received 272 bytes.
22:42:52.9613313[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Request is fully sent.
22:42:52.9647602[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Received response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:42:52 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}
22:42:52.9682997[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: CopyFromBufferAsync, message: Copying 46 bytes to stream.
22:42:52.9686556[RequestStop]
22:42:52.9693077[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: ReturnConnection, message: Stored connection in pool.
22:42:52.9698588[ClientSendCompleted] responseString: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:42:52 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}, httpRequestMessageHash: 11429296, httpResponseMessageHash: 28379535, httpClientHash: 59941933

200 OK
<html><body><h1>It works!</h1></body></html>


#2
GET http://localhost/

22:42:52.9743191[RequestStart] scheme: http, host: localhost, port: 80, pathAndQuery: /, versionMajor: 1, versionMinor: 1
22:42:52.9752029[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: GetOrReserveHttp11ConnectionAsync, message: Found usable connection in pool.
22:42:52.9754916[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: SendAsyncCore, message: Sending request: Method: GET, RequestUri: 'http://localhost/', Version: 1.1, Content: <null>, Headers:
{
}
22:42:52.9758922[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: WriteToStreamAsync, message: Writing 35 bytes.
22:42:52.9761684[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: LogBuffer, buffer: System.Byte[]
22:42:52.9770676[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#35236192, memberName: LogBuffer, buffer: System.Byte[]
22:42:52.9782194[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: SendAsyncCore, message: Received 272 bytes.
22:42:52.9784980[Associate] thisOrContextObject: HttpResponseMessage#48209832, memberName: RequestMessage, first: HttpResponseMessage#48209832, second: HttpRequestMessage#26517107
22:42:52.9790274[Info] thisOrContextObject: HttpConnectionResponseContent#5773521, memberName: .ctor, message:
22:42:52.9792394[Associate] thisOrContextObject: HttpResponseMessage#48209832, memberName: Content, first: HttpResponseMessage#48209832, second: HttpConnectionResponseContent#5773521
22:42:52.9795244[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: SendAsyncCore, message: Request is fully sent.
22:42:52.9798857[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: SendAsyncCore, message: Received response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:42:52 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}
22:42:52.9812620[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 26517107, memberName: CopyFromBufferAsync, message: Copying 46 bytes to stream.
22:42:52.9815394[RequestStop]
22:42:52.9818202[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: ReturnConnection, message: Stored connection in pool.
22:42:52.9820452[ClientSendCompleted] responseString: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:42:52 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}, httpRequestMessageHash: 26517107, httpResponseMessageHash: 48209832, httpClientHash: 59941933

200 OK
<html><body><h1>It works!</h1></body></html>
5.0 RC 1
➜ HttpTest-5.0-rc1  dotnet run -c release
.NET 5.0.0-rc.1.20451.14
22:44:42.9851982[Info] thisOrContextObject: HttpClientHandler#32854180, memberName: .ctor, message: 
22:44:43.0062352[Info] thisOrContextObject: SocketsHttpHandler#27252167, memberName: .ctor, message:
22:44:43.0076672[Info] thisOrContextObject: DiagnosticsHandler#43942917, memberName: .ctor, message:
22:44:43.0079784[Associate] thisOrContextObject: DiagnosticsHandler#43942917, memberName: InnerHandler, first: DiagnosticsHandler#43942917, second: SocketsHttpHandler#27252167
22:44:43.0104055[Associate] thisOrContextObject: HttpClient#59941933, memberName: .ctor, first: HttpClient#59941933, second: HttpClientHandler#32854180

#1
GET http://localhost/

22:44:43.0182075[RequestStart] scheme: http, host: localhost, port: 80, pathAndQuery: /, versionMajor: 1, versionMinor: 1, versionPolicy: 0
22:44:43.0555965[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: .ctor, message: AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null)
22:44:43.0558503[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: .ctor, message: _useProxy=True
22:44:43.0560485[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: TryCreate, message: AutoSettingsUsed, calling WinHttpOpen
22:44:43.0614976[Info] thisOrContextObject: HttpConnectionHandler#23458411, memberName: .ctor, message:
22:44:43.0617260[Info] thisOrContextObject: RedirectHandler#9799115, memberName: .ctor, message:
22:44:43.0656138[ErrorMessage] thisOrContextObject: WinInetProxyHelper#2606490, memberName: GetProxyForUrl, message: error=12180
22:44:43.0658231[Info] thisOrContextObject: WinInetProxyHelper#2606490, memberName: GetProxyForUrl, message: useProxy=False
22:44:43.0676869[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: .ctor, message: HttpConnectionPool http://localhost:80
22:44:43.0708068[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: IncrementConnectionCountNoLock, message:
22:44:43.0710723[HandlerMessage] poolId: 21083178, workerId: 0, requestId: 0, memberName: GetHttpConnectionAsync, message: Creating new connection for pool.
22:44:43.0765486[Info] thisOrContextObject: Socket#55530882, memberName: .ctor, message: InterNetworkV6
22:44:43.0796413[ResolutionStart] hostNameOrAddress: 
22:44:43.0863246[ResolutionStop]
22:44:43.0870359[Info] thisOrContextObject: (null), memberName: GetHostName, message: knatalia-P53
22:44:43.0879841[Info] thisOrContextObject: (null), memberName: CreateSocket, message: SafeSocketHandle:30015890(0x3FC)
22:44:43.0883055[Info] thisOrContextObject: Socket#55530882, memberName: SetSocketOption, message: optionLevel:Tcp optionName:NoDelay optionValue:1
22:44:43.0889465[Info] thisOrContextObject: Socket#55530882, memberName: SetSocketOption, message: SetSockOpt returns errorCode:Success
22:44:43.0891704[Info] thisOrContextObject: Socket#55530882, memberName: SetSocketOption, message: optionLevel:IPv6 optionName:IPv6Only optionValue:0
22:44:43.0894009[Info] thisOrContextObject: Socket#55530882, memberName: SetSocketOption, message: SetSockOpt returns errorCode:Success
22:44:43.0910378[Info] thisOrContextObject: AwaitableSocketAsyncEventArgs#1707556, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#15368010
22:44:43.0913709[ConnectedAsyncDns] socketHash: 55530882
22:44:43.0933471[ResolutionStart] hostNameOrAddress: localhost
22:44:43.1041238[ResolutionStop] 
22:44:43.1045104[Info] thisOrContextObject: SocketAsyncEventArgs#6044116, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#59817589
22:44:43.1050499[Info] thisOrContextObject: Socket#55530882, memberName: WildcardBindForConnectIfNecessary, message: ::
22:44:43.1060531[ConnectStart] address: InterNetworkV6:28:{0,80,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0,0,0,0}
22:44:43.1063909[Info] thisOrContextObject: SafeSocketHandle#30015890, memberName: GetOrAllocateThreadPoolBoundHandle, message: calling ThreadPool.BindHandle()
22:44:43.1108188[Connected] localEp: IPEndPoint#1150482023, remoteEp: (null), socketHash: 55530882
22:44:43.1110389[ConnectStop]
22:44:43.1112749[Info] thisOrContextObject: Socket#55530882, memberName: SetToConnected, message: now connected
22:44:43.1138452[Info] thisOrContextObject: Socket#55530882, memberName: Connected, message: _isConnected:True
22:44:43.1140932[ConnectionEstablished] versionMajor: 1, versionMinor: 1
22:44:43.1143803[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: TraceConnection, message: HttpConnection(HttpConnectionPool http://localhost:80)
22:44:43.1170835[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Sending request: Method: GET, RequestUri: 'http://localhost/', Version: 1.1, Content: <null>, Headers:
{
}
22:44:43.1176409[RequestHeadersStart]
22:44:43.1189413[RequestHeadersStop]
22:44:43.1192126[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: WriteToStreamAsync, message: Writing 35 bytes.
22:44:43.1194626[Info] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: InitializeInternals, message: new PreAllocatedOverlapped PreAllocatedOverlapped#31364015
22:44:43.1203271[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: LogBuffer, buffer: System.Byte[]
22:44:43.1205803[Associate] thisOrContextObject: HttpResponseMessage#28379535, memberName: RequestMessage, first: HttpResponseMessage#28379535, second: HttpRequestMessage#11429296
22:44:43.1207375[Info] thisOrContextObject: HttpConnectionResponseContent#64109423, memberName: .ctor, message:
22:44:43.1208491[Associate] thisOrContextObject: HttpResponseMessage#28379535, memberName: Content, first: HttpResponseMessage#28379535, second: HttpConnectionResponseContent#64109423
22:44:43.1352238[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#1707556, memberName: LogBuffer, buffer: System.Byte[]
22:44:43.1358748[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: FillAsync, message: Received 272 bytes.
22:44:43.1371597[ResponseHeadersStart]
22:44:43.1410291[ResponseHeadersStop]
22:44:43.1413229[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Request is fully sent.
22:44:43.1445998[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: SendAsyncCore, message: Received response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:44:43 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}
22:44:43.1467810[ResponseContentStart]
22:44:43.1476227[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 11429296, memberName: CopyFromBufferAsync, message: Copying 46 bytes to stream.
22:44:43.1481601[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: ReturnConnection, message: Stored connection in pool.
22:44:43.1486104[ClientSendCompleted] responseString: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:44:43 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}, httpRequestMessageHash: 11429296, httpResponseMessageHash: 28379535, httpClientHash: 59941933
22:44:43.1495825[ResponseContentStop]
22:44:43.1497322[RequestStop]

200 OK
<html><body><h1>It works!</h1></body></html>


#2
GET http://localhost/

22:44:43.1518377[RequestStart] scheme: http, host: localhost, port: 80, pathAndQuery: /, versionMajor: 1, versionMinor: 1, versionPolicy: 0
22:44:43.1523636[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: GetOrReserveHttp11ConnectionAsync, message: Found usable connection in pool.
22:44:43.1526806[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: SendAsyncCore, message: Sending request: Method: GET, RequestUri: 'http://localhost/', Version: 1.1, Content: <null>, Headers:
{
}
22:44:43.1530349[RequestHeadersStart]
22:44:43.1531862[RequestHeadersStop]
22:44:43.1533902[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: WriteToStreamAsync, message: Writing 35 bytes.
22:44:43.1536302[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#41622463, memberName: LogBuffer, buffer: System.Byte[]
22:44:43.1547793[DumpBuffer] thisOrContextObject: AwaitableSocketAsyncEventArgs#1707556, memberName: LogBuffer, buffer: System.Byte[]
22:44:43.1550428[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: SendAsyncCore, message: Received 272 bytes.
22:44:43.1552407[Associate] thisOrContextObject: HttpResponseMessage#803548, memberName: RequestMessage, first: HttpResponseMessage#803548, second: HttpRequestMessage#58998806
22:44:43.1554858[Info] thisOrContextObject: HttpConnectionResponseContent#26517107, memberName: .ctor, message:
22:44:43.1556766[Associate] thisOrContextObject: HttpResponseMessage#803548, memberName: Content, first: HttpResponseMessage#803548, second: HttpConnectionResponseContent#26517107
22:44:43.1558318[ResponseHeadersStart]
22:44:43.1559383[ResponseHeadersStop]
22:44:43.1561241[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: SendAsyncCore, message: Request is fully sent.
22:44:43.1563498[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: SendAsyncCore, message: Received response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:44:43 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}
22:44:43.1575909[ResponseContentStart] 
22:44:43.1577866[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 58998806, memberName: CopyFromBufferAsync, message: Copying 46 bytes to stream.
22:44:43.1580002[HandlerMessage] poolId: 21083178, workerId: 12547953, requestId: 0, memberName: ReturnConnection, message: Stored connection in pool.
22:44:43.1582698[ClientSendCompleted] responseString: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Wed, 13 Dec 2023 22:44:43 GMT
  Server: Apache/2.4.58
  Server: (Win64)
  ETag: "2e-60c69cce8b49a"
  Accept-Ranges: bytes
  Last-Modified: Wed, 13 Dec 2023 20:13:29 GMT
  Content-Length: 46
  Content-Type: text/html
}, httpRequestMessageHash: 58998806, httpResponseMessageHash: 803548, httpClientHash: 59941933
22:44:43.1595211[ResponseContentStop]
22:44:43.1596802[RequestStop]

200 OK
<html><body><h1>It works!</h1></body></html>

The server is also a default Apache listening on localhost.

The whole project for the preview 8 version is in HttpTest-5.0-p8.zip. For rc1, you’d need to change SDK in global.json:

{
  "sdk": {
-   "version": "5.0.100-preview.8.20417.9",
+   "version": "5.0.100-rc.1.20452.10",
    "rollForward": "disable"
  }
}

I don’t know whether you already leveraging local .NET installations, but just in case, here’s how to add it (example is for Windows, but there are also docs for Linux in https://learn.microsoft.com/en-us/dotnet/core/tools/dotnet-install-script):

cd <path-to-projects>\HttpTest-5.0-p8
<path-to-script>\dotnet-install.ps1 -Version 5.0.100-preview.8.20417.9 -i '.\.dotnet\'

To verify, you can call dotnet --info

➜  HttpTest-5.0-p8 dotnet --info
.NET SDK (reflecting any global.json):
 Version:   5.0.100-preview.8.20417.9 <--------
 Commit:    fc62663a35

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22621
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\.....\HttpTest-5.0-p8\.dotnet\sdk\5.0.100-preview.8.20417.9\ <--------

Host (useful for support):
  Version: 5.0.0-preview.8.20407.11 <--------
  Commit:  bf456654f9

.....rest omitted for brevity

For RC 1, it would be -Version 5.0.100-rc.1.20452.10 instead

I went back and downloaded Powershell versions until I found exactly where it broke. The last version that works for me is 7.1.0-preview.7. The next version (7.1.0-rc.1) fails. Each had a different release of .NET 5.

Sure enough, the code works in dotnet-5.0.100-preview.8 and fails in dotnet-5.0.100-rc.1, matching the powershell breakage.

Many thanks for the detailed response. It may take me a bit to implement it all, but I will get back to you as soon as I can with the results.

dotnet-5.0.408> .\dotnet new web --name TestCase dotnet-5.0.408> cd TestCase TestCase> cp <path_to_above_code>\Program.cs . TestCase> …\dotnet run

TestCase.zip

The loopback server is just a default Apache listening on 127.0.0.1

(Hopefully I’m not too far off of the correct way to do this, I’m not a .NET developer, just a guy who is trying to get his PowerShell scripts to work again.)

Disabling each in turn made no difference (nor did turning them both off together).