diff --git a/src/System.Private.ServiceModel/tests/Scenarios/Extensibility/WebSockets/WebSocketTests.4.1.0.cs b/src/System.Private.ServiceModel/tests/Scenarios/Extensibility/WebSockets/WebSocketTests.4.1.0.cs index 6ec253ff7bb..ff54065c269 100644 --- a/src/System.Private.ServiceModel/tests/Scenarios/Extensibility/WebSockets/WebSocketTests.4.1.0.cs +++ b/src/System.Private.ServiceModel/tests/Scenarios/Extensibility/WebSockets/WebSocketTests.4.1.0.cs @@ -1,4 +1,4 @@ -// Licensed to the .NET Foundation under one or more agreements. +// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. @@ -168,12 +168,9 @@ public static void WebSocket_Http_Duplex_Buffered(NetHttpMessageEncoding message "The logging done by the Server was not returned via the Callback."); // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -240,12 +237,9 @@ public static void WebSocket_Http_Duplex_Buffered_KeepAlive(NetHttpMessageEncodi "The logging done by the Server was not returned via the Callback."); // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -479,12 +473,9 @@ public static void WebSocket_Http_RequestReply_Streamed(NetHttpMessageEncoding m } // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -537,12 +528,9 @@ public static void WebSocket_Http_RequestReply_Buffered(NetHttpMessageEncoding m } // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -595,12 +583,9 @@ public static void WebSocket_Http_RequestReply_Buffered_KeepAlive(NetHttpMessage } // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -654,12 +639,9 @@ public static void WebSocket_Https_RequestReply_Buffered(NetHttpMessageEncoding } // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -715,12 +697,9 @@ public static void WebSocket_Https_RequestReply_Buffered_KeepAlive(NetHttpMessag } // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { @@ -885,12 +864,9 @@ public static void WebSocket_Http_VerifyWebSocketsUsed() Assert.True(responseFromService, String.Format("Response from the service was not expected. Expected: 'True' but got {0}", responseFromService)); // *** CLEANUP *** \\ - // Close the client and channel factory if not running on localhost. CoreWCF has a bug in Close method (on Linux). - if (!ScenarioTestHelpers.IsLocalHost()) - { - ((ICommunicationObject)client).Close(); - channelFactory.Close(); - } + // Close the client and channel factory. + ((ICommunicationObject)client).Close(); + channelFactory.Close(); } finally { diff --git a/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/CoreWCF/WebSocketDiagnostics.cs b/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/CoreWCF/WebSocketDiagnostics.cs new file mode 100644 index 00000000000..0728c3c5620 --- /dev/null +++ b/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/CoreWCF/WebSocketDiagnostics.cs @@ -0,0 +1,200 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +#if NET +using System; +using System.Diagnostics; +using System.IO.Pipelines; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Connections; + +namespace WcfService +{ + // Diagnostics for the WebSocket Kestrel listeners on the SelfHostedCoreWcfService. + // + // Captures, in the Helix console log, the precise lifecycle of every TCP + // connection that reaches the WebSocket endpoints (ports 8083/8084): + // * timestamped open / close / exception events tagged [WSDIAG] + // * connection-id correlation with Kestrel trace logging + // * byte-level outbound sniffing on the IDuplexPipe transport so we can + // prove whether the server ever wrote a WebSocket Close frame (first + // byte 0x88 = FIN+opcode Close, unmasked server-to-client) before + // Kestrel's transport sent TCP FIN. This isolates whether the + // "remote party closed without completing the close handshake" race + // on Helix (issue #5818) is caused by a missing server-side Close + // frame or by a Kestrel teardown that races the close-frame flush. + internal sealed class WebSocketDiagnosticsConnectionMiddleware + { + internal const string Tag = "[WSDIAG]"; + private static long s_seq; + + private readonly ConnectionDelegate _next; + private readonly string _listener; + + public WebSocketDiagnosticsConnectionMiddleware(ConnectionDelegate next, string listener) + { + _next = next; + _listener = listener; + } + + public async Task OnConnectionAsync(ConnectionContext connection) + { + long n = Interlocked.Increment(ref s_seq); + Stopwatch sw = Stopwatch.StartNew(); + string connId = connection.ConnectionId; + string remote = connection.RemoteEndPoint?.ToString() ?? "?"; + string local = connection.LocalEndPoint?.ToString() ?? "?"; + + Write($"open #{n} listener={_listener} id={connId} remote={remote} local={local}"); + + IDuplexPipe original = connection.Transport; + SniffingDuplexPipe sniff = new SniffingDuplexPipe(original, connId, n, sw); + connection.Transport = sniff; + + CancellationTokenRegistration ctr = connection.ConnectionClosed.Register(() => + { + Write($"connclosed-token #{n} id={connId} elapsedMs={sw.ElapsedMilliseconds} {sniff.SummaryLine()}"); + }); + + try + { + await _next(connection); + Write($"pipeline-completed #{n} id={connId} elapsedMs={sw.ElapsedMilliseconds} {sniff.SummaryLine()}"); + } + catch (Exception ex) + { + Write($"pipeline-exception #{n} id={connId} elapsedMs={sw.ElapsedMilliseconds} type={ex.GetType().FullName} msg={Sanitize(ex.Message)}"); + Write($"pipeline-exception-stack #{n} id={connId} {Sanitize(ex.ToString())}"); + throw; + } + finally + { + ctr.Dispose(); + Write($"close #{n} id={connId} totalMs={sw.ElapsedMilliseconds} {sniff.SummaryLine()}"); + } + } + + internal static void Write(string line) + { + Console.WriteLine($"{Tag} {DateTime.UtcNow:HH:mm:ss.fffffff} {line}"); + } + + private static string Sanitize(string s) => + s is null ? string.Empty : s.Replace("\r", " ").Replace("\n", " | "); + } + + // Wraps the connection's IDuplexPipe so we can observe outbound bytes + // written by the application. We do not modify any bytes; we only + // timestamp + log opcode bytes of each outbound write so we can prove + // whether a WebSocket Close frame was emitted before the socket's send + // loop completed. + internal sealed class SniffingDuplexPipe : IDuplexPipe + { + private readonly SniffingPipeWriter _output; + private readonly IDuplexPipe _inner; + + public SniffingDuplexPipe(IDuplexPipe inner, string connId, long seq, Stopwatch sw) + { + _inner = inner; + _output = new SniffingPipeWriter(inner.Output, connId, seq, sw); + } + + public PipeReader Input => _inner.Input; + public PipeWriter Output => _output; + + public string SummaryLine() => _output.SummaryLine(); + } + + internal sealed class SniffingPipeWriter : PipeWriter + { + private readonly PipeWriter _inner; + private readonly string _connId; + private readonly long _seq; + private readonly Stopwatch _sw; + + private Memory _lastMemory; + private long _totalBytes; + private int _writeCount; + private bool _closeFrameSeen; + private long _closeFrameElapsedMs = -1; + private byte _lastFirstByte; + + public SniffingPipeWriter(PipeWriter inner, string connId, long seq, Stopwatch sw) + { + _inner = inner; + _connId = connId; + _seq = seq; + _sw = sw; + } + + private void Inspect(ReadOnlySpan span, string source) + { + if (span.Length == 0) return; + + _writeCount++; + _totalBytes += span.Length; + _lastFirstByte = span[0]; + + // Server-to-client frames are unmasked. WebSocket frame header + // byte layout: FIN(1) RSV(3) Opcode(4). Close opcode = 0x8. + // FIN+Close => 0x88. + if ((span[0] & 0x0F) == 0x08 && (span[0] & 0x80) == 0x80) + { + if (!_closeFrameSeen) + { + _closeFrameSeen = true; + _closeFrameElapsedMs = _sw.ElapsedMilliseconds; + int dumpLen = Math.Min(span.Length, 16); + string hex = Convert.ToHexString(span.Slice(0, dumpLen)); + WebSocketDiagnosticsConnectionMiddleware.Write( + $"out-close-frame #{_seq} id={_connId} via={source} elapsedMs={_closeFrameElapsedMs} firstByte=0x{span[0]:X2} dump={hex}"); + } + } + } + + public override void Advance(int bytes) + { + if (bytes > 0 && _lastMemory.Length >= bytes) + { + Inspect(_lastMemory.Span.Slice(0, bytes), "GetMemory+Advance"); + } + _inner.Advance(bytes); + } + + public override Memory GetMemory(int sizeHint = 0) + { + _lastMemory = _inner.GetMemory(sizeHint); + return _lastMemory; + } + + public override Span GetSpan(int sizeHint = 0) + { + _lastMemory = _inner.GetMemory(sizeHint); + return _lastMemory.Span; + } + + public override ValueTask WriteAsync(ReadOnlyMemory source, CancellationToken cancellationToken = default) + { + Inspect(source.Span, "WriteAsync"); + return _inner.WriteAsync(source, cancellationToken); + } + + public override ValueTask FlushAsync(CancellationToken cancellationToken = default) + => _inner.FlushAsync(cancellationToken); + + public override void CancelPendingFlush() => _inner.CancelPendingFlush(); + + public override void Complete(Exception exception = null) + { + WebSocketDiagnosticsConnectionMiddleware.Write( + $"output-complete #{_seq} id={_connId} elapsedMs={_sw.ElapsedMilliseconds} totalBytes={_totalBytes} writes={_writeCount} closeFrameSent={_closeFrameSeen} ex={exception?.GetType().Name ?? "null"}"); + _inner.Complete(exception); + } + + public string SummaryLine() => + $"writes={_writeCount} totalBytes={_totalBytes} closeFrameSent={_closeFrameSeen} closeFrameElapsedMs={_closeFrameElapsedMs} lastFirstByte=0x{_lastFirstByte:X2}"; + } +} +#endif diff --git a/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/TestDefinitionHelper.cs b/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/TestDefinitionHelper.cs index a9b1f017fa7..facb4b42f45 100644 --- a/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/TestDefinitionHelper.cs +++ b/src/System.Private.ServiceModel/tools/IISHostedWcfService/App_code/TestDefinitionHelper.cs @@ -82,17 +82,34 @@ internal static async Task StartHosts(bool useWebSocket) builder.Logging.AddFilter("Microsoft", LogLevel.Debug); builder.Logging.SetMinimumLevel(LogLevel.Debug); + // Diagnostics for WebSocket close-handshake race on Helix Linux (issue #5818). + // Capture connection lifecycle, raw TCP byte counts + FIN/RST events, and + // WebSocket close-frame events in the SelfHostedCoreWCFService stdout so they + // surface in the Helix console log next to the test failure. + if (useWebSocket) + { + builder.Logging.AddFilter("Microsoft.AspNetCore.Server.Kestrel", LogLevel.Trace); + builder.Logging.AddFilter("Microsoft.AspNetCore.Server.Kestrel.Connections", LogLevel.Trace); + builder.Logging.AddFilter("Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets", LogLevel.Trace); + builder.Logging.AddFilter("Microsoft.AspNetCore.WebSockets", LogLevel.Trace); + builder.Logging.AddFilter("CoreWCF", LogLevel.Trace); + } + builder.WebHost.ConfigureKestrel(options => { options.AllowSynchronousIO = true; if (useWebSocket) { - options.Listen(IPAddress.IPv6Any, new Uri(BaseAddresses[ServiceSchema.WS]).Port); + options.Listen(IPAddress.IPv6Any, new Uri(BaseAddresses[ServiceSchema.WS]).Port, listenOptions => + { + listenOptions.Use(next => new WebSocketDiagnosticsConnectionMiddleware(next, "ws-http").OnConnectionAsync); + }); options.Listen(IPAddress.IPv6Any, new Uri(BaseAddresses[ServiceSchema.WSS]).Port, listenOptions => { X509Certificate2 cert = TestHost.CertificateFromFriendlyName(StoreName.My, StoreLocation.LocalMachine, "WCF Bridge - Machine certificate generated by the CertificateManager"); listenOptions.UseHttps(cert); + listenOptions.Use(next => new WebSocketDiagnosticsConnectionMiddleware(next, "ws-https").OnConnectionAsync); if (Debugger.IsAttached) {