From ffbb975d98ac914ed8840c9bee1ee2a6b5e485b1 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 3 Sep 2020 16:12:58 +0200 Subject: [PATCH 01/27] Correct NameResolutionTelemetry logic Taken from c4c9a2f99b7e339388199086d3014041abccc21e --- .../src/System/Net/Dns.cs | 48 ++++++++----------- 1 file changed, 20 insertions(+), 28 deletions(-) diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs index 98cb7ccbc0b55..60cc964ec08ce 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -466,34 +466,9 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR if (NameResolutionTelemetry.Log.IsEnabled()) { - ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); - - Task coreTask; - try - { - coreTask = NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); - } - catch when (LogFailure(stopwatch)) - { - Debug.Fail("LogFailure should return false"); - throw; - } - - coreTask.ContinueWith( - (task, state) => - { - NameResolutionTelemetry.Log.AfterResolution( - stopwatch: (ValueStopwatch)state!, - successful: task.IsCompletedSuccessfully); - }, - state: stopwatch, - cancellationToken: default, - TaskContinuationOptions.ExecuteSynchronously, - TaskScheduler.Default); - - // coreTask is not actually a base Task, but Task / Task - // We have to return it and not the continuation - return coreTask; + return justAddresses + ? (Task)GetAddrInfoWithTelemetryAsync(hostName, justAddresses) + : (Task)GetAddrInfoWithTelemetryAsync(hostName, justAddresses); } else { @@ -506,6 +481,23 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR RunAsync(s => GetHostEntryCore((string)s), hostName); } + private static async Task GetAddrInfoWithTelemetryAsync(string hostName, bool justAddresses) + where T : class + { + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); + + T? result = null; + try + { + result = await ((Task)NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses)).ConfigureAwait(false); + return result; + } + finally + { + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: result is not null); + } + } + private static Task RunAsync(Func func, object arg) => Task.Factory.StartNew(func!, arg, CancellationToken.None, TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); From 29b9221c6ce1a724bd8fdbb0649c98d0dcb7d0d8 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Sun, 13 Sep 2020 23:59:49 +0200 Subject: [PATCH 02/27] Enable listening to multiple sources with TestEventListener --- .../Diagnostics/Tracing/TestEventListener.cs | 97 ++++++++----------- 1 file changed, 43 insertions(+), 54 deletions(-) diff --git a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs index b12f5022c62f1..717d39684573a 100644 --- a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs +++ b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs @@ -9,90 +9,79 @@ namespace System.Diagnostics.Tracing /// Simple event listener than invokes a callback for each event received. internal sealed class TestEventListener : EventListener { - private readonly string _targetSourceName; - private readonly Guid _targetSourceGuid; - private readonly EventLevel _level; + private readonly Dictionary _names = new Dictionary(); + private readonly Dictionary _guids = new Dictionary(); + private readonly double? _eventCounterInterval; private Action _eventWritten; - private List _tmpEventSourceList = new List(); + private readonly List _eventSourceList = new List(); public TestEventListener(string targetSourceName, EventLevel level, double? eventCounterInterval = null) { - // Store the arguments - _targetSourceName = targetSourceName; - _level = level; _eventCounterInterval = eventCounterInterval; - - LoadSourceList(); + AddSource(targetSourceName, level); } public TestEventListener(Guid targetSourceGuid, EventLevel level, double? eventCounterInterval = null) { - // Store the arguments - _targetSourceGuid = targetSourceGuid; - _level = level; _eventCounterInterval = eventCounterInterval; - - LoadSourceList(); + AddSource(targetSourceGuid, level); } - private void LoadSourceList() + public void AddSource(string name, EventLevel level, EventKeywords keywords = EventKeywords.All) => + AddSource(name, null, level, keywords); + + public void AddSource(Guid guid, EventLevel level, EventKeywords keywords = EventKeywords.All) => + AddSource(null, guid, level, keywords); + + private void AddSource(string name, Guid? guid, EventLevel level, EventKeywords keywords) { - // The base constructor, which is called before this constructor, - // will invoke the virtual OnEventSourceCreated method for each - // existing EventSource, which means OnEventSourceCreated will be - // called before _targetSourceGuid and _level have been set. As such, - // we store a temporary list that just exists from the moment this instance - // is created (instance field initializers run before the base constructor) - // and until we finish construction... in that window, OnEventSourceCreated - // will store the sources into the list rather than try to enable them directly, - // and then here we can enumerate that list, then clear it out. - List sources; - lock (_tmpEventSourceList) - { - sources = _tmpEventSourceList; - _tmpEventSourceList = null; - } - foreach (EventSource source in sources) + lock (_eventSourceList) { - EnableSourceIfMatch(source); + if (name is not null) + _names.Add(name, (level, keywords)); + + if (guid.HasValue) + _guids.Add(guid.Value, (level, keywords)); + + foreach (EventSource source in _eventSourceList) + { + if (name == source.Name || guid == source.Guid) + { + EnableEventSource(source, level, keywords); + } + } } } + public void AddActivityTracking() => + AddSource("System.Threading.Tasks.TplEventSource", EventLevel.Informational, (EventKeywords)0x80 /* TasksFlowActivityIds */); + protected override void OnEventSourceCreated(EventSource eventSource) { - List tmp = _tmpEventSourceList; - if (tmp != null) + lock (_eventSourceList) { - lock (tmp) + _eventSourceList.Add(eventSource); + + if (_names.TryGetValue(eventSource.Name, out (EventLevel Level, EventKeywords Keywords) settings) || + _guids.TryGetValue(eventSource.Guid, out settings)) { - if (_tmpEventSourceList != null) - { - _tmpEventSourceList.Add(eventSource); - return; - } + EnableEventSource(eventSource, settings.Level, settings.Keywords); } } - - EnableSourceIfMatch(eventSource); } - private void EnableSourceIfMatch(EventSource source) + private void EnableEventSource(EventSource source, EventLevel level, EventKeywords keywords) { - if (source.Name.Equals(_targetSourceName) || - source.Guid.Equals(_targetSourceGuid)) + var args = new Dictionary(); + + if (_eventCounterInterval != null) { - if (_eventCounterInterval != null) - { - var args = new Dictionary { { "EventCounterIntervalSec", _eventCounterInterval?.ToString() } }; - EnableEvents(source, _level, EventKeywords.All, args); - } - else - { - EnableEvents(source, _level); - } + args.Add("EventCounterIntervalSec", _eventCounterInterval.ToString()); } + + EnableEvents(source, level, keywords, args); } public void RunWithCallback(Action handler, Action body) From cf57e1867e0eca52ae79f1f409d142cab29347b7 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 14 Sep 2020 00:00:40 +0200 Subject: [PATCH 03/27] Workaround EventWrittenEventArgs bug when the EventArgs are stored Workaround https://github.com/dotnet/runtime/issues/42128 --- .../tests/System/Diagnostics/Tracing/TestEventListener.cs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs index 717d39684573a..820b37401581d 100644 --- a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs +++ b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Collections.Generic; +using System.Reflection; using System.Threading.Tasks; namespace System.Diagnostics.Tracing @@ -98,8 +99,14 @@ public async Task RunWithCallbackAsync(Action handler, Fu finally { _eventWritten = null; } } + // Workaround for being able to inspect the ActivityId property after storing EventWrittenEventArgs + // [ActiveIssue("https://github.com/dotnet/runtime/issues/42128")] + private static readonly FieldInfo s_activityIdFieldInfo = + typeof(EventWrittenEventArgs).GetField("m_activityId", BindingFlags.NonPublic | BindingFlags.Instance); + protected override void OnEventWritten(EventWrittenEventArgs eventData) { + s_activityIdFieldInfo.SetValue(eventData, eventData.ActivityId); _eventWritten?.Invoke(eventData); } } From 9b7c93f54f1db4f083fc6c1667e8d6124f79283f Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 14 Sep 2020 05:27:28 +0200 Subject: [PATCH 04/27] Correct System.Net.Sockets Telemetry --- .../src/System/Net/Sockets/Socket.cs | 64 ++- .../Sockets/SocketAsyncEventArgs.Windows.cs | 12 + .../Net/Sockets/SocketAsyncEventArgs.cs | 74 ++- .../System/Net/Sockets/SocketPal.Windows.cs | 5 +- .../System/Net/Sockets/SocketsTelemetry.cs | 89 ++-- .../tests/FunctionalTests/TelemetryTest.cs | 445 +++++++++++++++++- 6 files changed, 580 insertions(+), 109 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index ce976d0fd8b2a..3ad0a656418c5 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -1110,19 +1110,15 @@ public Socket Accept() ref socketAddress.InternalSize, out acceptedSocketHandle); + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); + // Throw an appropriate SocketException if the native call fails. if (errorCode != SocketError.Success) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptFailedAndStop(errorCode, null); - Debug.Assert(acceptedSocketHandle.IsInvalid); UpdateAcceptSocketErrorForDisposed(ref errorCode); UpdateStatusAfterSocketErrorAndThrowException(errorCode); } - else - { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStop(); - } Debug.Assert(!acceptedSocketHandle.IsInvalid); @@ -2140,7 +2136,13 @@ private bool CanUseConnectEx(EndPoint remoteEP) internal IAsyncResult UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback? callback, object? state, bool flowContext = false) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStart(remoteEP); + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.ConnectStart(remoteEP); + + // Ignore flowContext when using Telemetry to avoid losing Activity tracking + flowContext = true; + } if (CanUseConnectEx(remoteEP)) { @@ -2363,7 +2365,15 @@ public void Disconnect(bool reuseSocket) // int - Return code from async Connect, 0 for success, SocketError.NotConnected otherwise public void EndConnect(IAsyncResult asyncResult) { - ThrowIfDisposed(); + if (Disposed) + { + if (SocketsTelemetry.Log.IsEnabled() && asyncResult is not MultipleAddressConnectAsyncResult) + { + SocketsTelemetry.Log.AfterConnect(SocketError.OperationAborted); + } + + ThrowObjectDisposedException(); + } // Validate input parameters. if (asyncResult == null) @@ -2391,10 +2401,14 @@ asyncResult as MultipleAddressConnectAsyncResult ?? if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"asyncResult:{asyncResult}"); Exception? ex = castedAsyncResult.Result as Exception; - if (ex != null || (SocketError)castedAsyncResult.ErrorCode != SocketError.Success) + + if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is not MultipleAddressConnectAsyncResult) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectFailedAndStop((SocketError)castedAsyncResult.ErrorCode, ex?.Message); + SocketsTelemetry.Log.AfterConnect((SocketError)castedAsyncResult.ErrorCode, ex?.Message); + } + if (ex != null || (SocketError)castedAsyncResult.ErrorCode != SocketError.Success) + { if (ex == null) { SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode; @@ -2409,8 +2423,6 @@ asyncResult as MultipleAddressConnectAsyncResult ?? ExceptionDispatchInfo.Throw(ex); } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStop(); - if (NetEventSource.Log.IsEnabled()) NetEventSource.Connected(this, LocalEndPoint, RemoteEndPoint); } @@ -3540,14 +3552,12 @@ private IAsyncResult BeginAcceptCommon(Socket? acceptSocket, int receiveSize, As // Throw an appropriate SocketException if the native call fails synchronously. if (!CheckErrorAndUpdateStatus(errorCode)) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptFailedAndStop(errorCode, null); + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); UpdateAcceptSocketErrorForDisposed(ref errorCode); throw new SocketException((int)errorCode); } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStop(); - // Finish the flow capture, maybe complete here. asyncResult.FinishPostingAsyncOp(ref Caches.AcceptClosureCache); @@ -3573,7 +3583,12 @@ public Socket EndAccept(IAsyncResult asyncResult) } private Socket EndAcceptCommon(out byte[]? buffer, out int bytesTransferred, IAsyncResult asyncResult) { - ThrowIfDisposed(); + if (Disposed) + { + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(SocketError.OperationAborted); + + ThrowObjectDisposedException(); + } // Validate input parameters. if (asyncResult == null) @@ -3594,21 +3609,20 @@ private Socket EndAcceptCommon(out byte[]? buffer, out int bytesTransferred, IAs bytesTransferred = (int)castedAsyncResult.BytesTransferred; buffer = castedAsyncResult.Buffer; + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.BytesReceived(bytesTransferred); + castedAsyncResult.EndCalled = true; // Throw an appropriate SocketException if the native call failed asynchronously. SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode; + + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); + if (errorCode != SocketError.Success) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptFailedAndStop(errorCode, null); - UpdateAcceptSocketErrorForDisposed(ref errorCode); UpdateStatusAfterSocketErrorAndThrowException(errorCode); } - else - { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStop(); - } if (NetEventSource.Log.IsEnabled()) NetEventSource.Accepted(socket, socket.RemoteEndPoint, socket.LocalEndPoint); return socket; @@ -4223,11 +4237,11 @@ private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socket SocketError errorCode = SocketPal.Connect(_handle, socketAddress.Buffer, socketAddress.Size); + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterConnect(errorCode); + // Throw an appropriate SocketException if the native call fails. if (errorCode != SocketError.Success) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectFailedAndStop(errorCode, null); - UpdateConnectSocketErrorForDisposed(ref errorCode); // Update the internal state of this socket according to the error before throwing. SocketException socketException = SocketExceptionFactory.CreateSocketException((int)errorCode, endPointSnapshot); @@ -4236,8 +4250,6 @@ private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socket throw socketException; } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStop(); - if (_rightEndPoint == null) { // Save a copy of the EndPoint so we can use it for Create(). diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.Windows.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.Windows.cs index 6368666ec6bf4..52b5355be26ba 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.Windows.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.Windows.cs @@ -155,6 +155,9 @@ private unsafe SocketError ProcessIOCPResult(bool success, int bytesTransferred, // so we can set the results right now. FreeNativeOverlapped(overlapped); FinishOperationSyncSuccess(bytesTransferred, SocketFlags.None); + + if (SocketsTelemetry.Log.IsEnabled()) AfterConnectAcceptTelemetry(); + return SocketError.Success; } @@ -170,6 +173,9 @@ private unsafe SocketError ProcessIOCPResult(bool success, int bytesTransferred, // Completed synchronously with a failure. FreeNativeOverlapped(overlapped); FinishOperationSyncFailure(socketError, bytesTransferred, SocketFlags.None); + + if (SocketsTelemetry.Log.IsEnabled()) AfterConnectAcceptTelemetry(); + return socketError; } @@ -202,6 +208,9 @@ private unsafe SocketError ProcessIOCPResultWithSingleBufferHandle(SocketError s _singleBufferHandleState = SingleBufferHandleState.None; FreeNativeOverlapped(overlapped); FinishOperationSyncSuccess(bytesTransferred, SocketFlags.None); + + if (SocketsTelemetry.Log.IsEnabled()) AfterConnectAcceptTelemetry(); + return SocketError.Success; } @@ -218,6 +227,9 @@ private unsafe SocketError ProcessIOCPResultWithSingleBufferHandle(SocketError s _singleBufferHandleState = SingleBufferHandleState.None; FreeNativeOverlapped(overlapped); FinishOperationSyncFailure(socketError, bytesTransferred, SocketFlags.None); + + if (SocketsTelemetry.Log.IsEnabled()) AfterConnectAcceptTelemetry(); + return socketError; } diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs index 114a65d256d70..23b159b4acf9d 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs @@ -198,11 +198,41 @@ public int BytesTransferred public event EventHandler? Completed; + private void OnCompletedInternal(SocketAsyncEventArgs e) + { + if (SocketsTelemetry.Log.IsEnabled()) + { + e.AfterConnectAcceptTelemetry(); + } + + OnCompleted(e); + } + protected virtual void OnCompleted(SocketAsyncEventArgs e) { Completed?.Invoke(e._currentSocket, e); } + private void AfterConnectAcceptTelemetry() + { + if (SocketsTelemetry.Log.IsEnabled()) + { + switch (LastOperation) + { + case SocketAsyncOperation.Accept: + SocketsTelemetry.Log.AfterAccept(SocketError); + break; + + case SocketAsyncOperation.Connect: + if (_multipleConnect is null) + { + SocketsTelemetry.Log.AfterConnect(SocketError); + } + break; + } + } + } + // DisconnectResuseSocket property. public bool DisconnectReuseSocket { @@ -420,7 +450,7 @@ internal void SetResults(Exception exception, int bytesTransferred, SocketFlags private static void ExecutionCallback(object? state) { var thisRef = (SocketAsyncEventArgs)state!; - thisRef.OnCompleted(thisRef); + thisRef.OnCompletedInternal(thisRef); } // Marks this object as no longer "in-use". Will also execute a Dispose deferred @@ -548,7 +578,13 @@ internal void StartOperationAccept() } } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStart(_currentSocket!._rightEndPoint!); + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AcceptStart(_currentSocket!._rightEndPoint!); + + // Ignore _flowExecutionContext when using Telemetry to avoid losing Activity tracking + _context = ExecutionContext.Capture(); + } } internal void StartOperationConnect(MultipleConnectAsync? multipleConnect, bool userSocket) @@ -558,7 +594,13 @@ internal void StartOperationConnect(MultipleConnectAsync? multipleConnect, bool _userSocket = userSocket; // Log only the actual connect operation to a remote endpoint. - if (SocketsTelemetry.Log.IsEnabled() && multipleConnect == null) SocketsTelemetry.Log.ConnectStart(_socketAddress!); + if (SocketsTelemetry.Log.IsEnabled() && multipleConnect == null) + { + SocketsTelemetry.Log.ConnectStart(_socketAddress!); + + // Ignore _flowExecutionContext when using Telemetry to avoid losing Activity tracking + _context = ExecutionContext.Capture(); + } } internal void CancelConnectAsync() @@ -572,8 +614,6 @@ internal void CancelConnectAsync() } else { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectCanceledAndStop(); - // Otherwise we're doing a normal ConnectAsync - cancel it by closing the socket. // _currentSocket will only be null if _multipleConnect was set, so we don't have to check. if (_currentSocket == null) @@ -589,12 +629,6 @@ internal void FinishOperationSyncFailure(SocketError socketError, int bytesTrans { SetResults(socketError, bytesTransferred, flags); - if (SocketsTelemetry.Log.IsEnabled()) - { - if (_multipleConnect == null && _completedOperation == SocketAsyncOperation.Connect) SocketsTelemetry.Log.ConnectFailedAndStop(socketError, null); - if (_completedOperation == SocketAsyncOperation.Accept) SocketsTelemetry.Log.AcceptFailedAndStop(socketError, null); - } - // This will be null if we're doing a static ConnectAsync to a DnsEndPoint with AddressFamily.Unspecified; // the attempt socket will be closed anyways, so not updating the state is OK. // If we're doing a static ConnectAsync to an IPEndPoint, we need to dispose @@ -640,7 +674,7 @@ internal void FinishOperationAsyncFailure(SocketError socketError, int bytesTran if (context == null) { - OnCompleted(this); + OnCompletedInternal(this); } else { @@ -656,7 +690,7 @@ internal void FinishConnectByNameAsyncFailure(Exception exception, int bytesTran if (context == null) { - OnCompleted(this); + OnCompletedInternal(this); } else { @@ -677,7 +711,7 @@ internal void FinishWrapperConnectSuccess(Socket? connectSocket, int bytesTransf Complete(); if (context == null) { - OnCompleted(this); + OnCompletedInternal(this); } else { @@ -715,13 +749,9 @@ internal void FinishOperationSyncSuccess(int bytesTransferred, SocketFlags flags } catch (ObjectDisposedException) { } } - - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStop(); } else { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptFailedAndStop(socketError, null); - SetResults(socketError, bytesTransferred, flags); _acceptSocket = null; _currentSocket.UpdateStatusAfterSocketError(socketError); @@ -741,16 +771,12 @@ internal void FinishOperationSyncSuccess(int bytesTransferred, SocketFlags flags catch (ObjectDisposedException) { } } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStop(); - // Mark socket connected. _currentSocket!.SetToConnected(); _connectSocket = _currentSocket; } else { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectFailedAndStop(socketError, null); - SetResults(socketError, bytesTransferred, flags); _currentSocket!.UpdateStatusAfterSocketError(socketError); } @@ -814,7 +840,7 @@ internal void FinishOperationAsyncSuccess(int bytesTransferred, SocketFlags flag // Raise completion event. if (context == null) { - OnCompleted(this); + OnCompletedInternal(this); } else { @@ -834,6 +860,8 @@ private void FinishOperationSync(SocketError socketError, int bytesTransferred, { FinishOperationSyncFailure(socketError, bytesTransferred, flags); } + + if (SocketsTelemetry.Log.IsEnabled()) AfterConnectAcceptTelemetry(); } private static void LogBytesTransferEvents(SocketType? socketType, SocketAsyncOperation operation, int bytesTransferred) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs index 1d7947523b12e..137c1377fd368 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs @@ -1304,7 +1304,6 @@ public static unsafe SocketError AcceptAsync(Socket socket, SafeSocketHandle han try { // This can throw ObjectDisposedException. - int bytesTransferred; bool success = socket.AcceptEx( handle, acceptHandle, @@ -1312,10 +1311,10 @@ public static unsafe SocketError AcceptAsync(Socket socket, SafeSocketHandle han receiveSize, addressBufferSize, addressBufferSize, - out bytesTransferred, + out int bytesReceived, asyncResult.DangerousOverlappedPointer); // SafeHandle was just created in SetUnmanagedStructures - return asyncResult.ProcessOverlappedResult(success, 0); + return asyncResult.ProcessOverlappedResult(success, bytesReceived); } catch { diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index f3430e7b7ed7d..0293707fc0609 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Diagnostics; using System.Diagnostics.Tracing; using System.Threading; @@ -26,17 +27,13 @@ internal sealed class SocketsTelemetry : EventSource private long _datagramsSent; [Event(1, Level = EventLevel.Informational)] - public void ConnectStart(string? address) + private void ConnectStart(string? address) { - Interlocked.Increment(ref _outgoingConnectionsEstablished); - if (IsEnabled(EventLevel.Informational, EventKeywords.All)) - { - WriteEvent(eventId: 1, address ?? ""); - } + WriteEvent(eventId: 1, address); } [Event(2, Level = EventLevel.Informational)] - public void ConnectStop() + private void ConnectStop() { if (IsEnabled(EventLevel.Informational, EventKeywords.All)) { @@ -45,16 +42,16 @@ public void ConnectStop() } [Event(3, Level = EventLevel.Error)] - public void ConnectFailed(SocketError error, string? exceptionMessage) + private void ConnectFailed(SocketError error, string? exceptionMessage) { if (IsEnabled(EventLevel.Error, EventKeywords.All)) { - WriteEvent(eventId: 3, (int)error, exceptionMessage ?? string.Empty); + WriteEvent(eventId: 3, (int)error, exceptionMessage); } } [Event(4, Level = EventLevel.Warning)] - public void ConnectCanceled() + private void ConnectCanceled() { if (IsEnabled(EventLevel.Warning, EventKeywords.All)) { @@ -63,17 +60,13 @@ public void ConnectCanceled() } [Event(5, Level = EventLevel.Informational)] - public void AcceptStart(string? address) + private void AcceptStart(string? address) { - Interlocked.Increment(ref _incomingConnectionsEstablished); - if (IsEnabled(EventLevel.Informational, EventKeywords.All)) - { - WriteEvent(eventId: 5, address ?? ""); - } + WriteEvent(eventId: 5, address); } [Event(6, Level = EventLevel.Informational)] - public void AcceptStop() + private void AcceptStop() { if (IsEnabled(EventLevel.Informational, EventKeywords.All)) { @@ -82,68 +75,98 @@ public void AcceptStop() } [Event(7, Level = EventLevel.Error)] - public void AcceptFailed(SocketError error, string? exceptionMessage) + private void AcceptFailed(SocketError error, string? exceptionMessage) { if (IsEnabled(EventLevel.Error, EventKeywords.All)) { - WriteEvent(eventId: 7, (int)error, exceptionMessage ?? string.Empty); + WriteEvent(eventId: 7, (int)error, exceptionMessage); } } [NonEvent] public void ConnectStart(Internals.SocketAddress address) { - ConnectStart(address.ToString()); + if (IsEnabled(EventLevel.Informational, EventKeywords.All)) + { + ConnectStart(address.ToString()); + } } [NonEvent] public void ConnectStart(EndPoint address) { - ConnectStart(address.ToString()); + if (IsEnabled(EventLevel.Informational, EventKeywords.All)) + { + ConnectStart(address.ToString()); + } } [NonEvent] - public void ConnectCanceledAndStop() + public void AfterConnect(SocketError error, string? exceptionMessage = null) { - ConnectCanceled(); - ConnectStop(); - } + if (error == SocketError.Success) + { + Debug.Assert(exceptionMessage is null); + Interlocked.Increment(ref _outgoingConnectionsEstablished); + } + else + { + if (error == SocketError.OperationAborted) + { + ConnectCanceled(); + } + + ConnectFailed(error, exceptionMessage); + } - [NonEvent] - public void ConnectFailedAndStop(SocketError error, string? exceptionMessage) - { - ConnectFailed(error, exceptionMessage); ConnectStop(); } [NonEvent] public void AcceptStart(Internals.SocketAddress address) { - AcceptStart(address.ToString()); + if (IsEnabled(EventLevel.Informational, EventKeywords.All)) + { + AcceptStart(address.ToString()); + } } [NonEvent] public void AcceptStart(EndPoint address) { - AcceptStart(address.ToString()); + if (IsEnabled(EventLevel.Informational, EventKeywords.All)) + { + AcceptStart(address.ToString()); + } } [NonEvent] - public void AcceptFailedAndStop(SocketError error, string? exceptionMessage) + public void AfterAccept(SocketError error, string? exceptionMessage = null) { - AcceptFailed(error, exceptionMessage); + if (error == SocketError.Success) + { + Debug.Assert(exceptionMessage is null); + Interlocked.Increment(ref _incomingConnectionsEstablished); + } + else + { + AcceptFailed(error, exceptionMessage); + } + AcceptStop(); } [NonEvent] public void BytesReceived(int count) { + Debug.Assert(count >= 0); Interlocked.Add(ref _bytesReceived, count); } [NonEvent] public void BytesSent(int count) { + Debug.Assert(count >= 0); Interlocked.Add(ref _bytesSent, count); } diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 783fbf52e133e..b82ab4f1de154 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -1,12 +1,11 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -using System.Collections; using System.Collections.Concurrent; using System.Collections.Generic; -using System.Diagnostics; using System.Diagnostics.Tracing; using System.Linq; +using System.Threading; using System.Threading.Tasks; using Microsoft.DotNet.RemoteExecutor; using Xunit; @@ -35,16 +34,351 @@ public static void EventSource_ExistsWithCorrectId() Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location)); } + public static IEnumerable SocketMethods_MemberData() + { + yield return new[] { "Sync" }; + yield return new[] { "Task" }; + yield return new[] { "Apm" }; + yield return new[] { "Eap" }; + } + + public static IEnumerable SocketMethods_Matrix_MemberData() + { + return from m1 in SocketMethods_MemberData() + from m2 in SocketMethods_MemberData() + select new[] { m1[0], m2[0] }; + } + + public static IEnumerable SocketMethods_WithBools_MemberData() + { + return from m1 in SocketMethods_MemberData() + from @bool in new[] { true, false } + select new[] { m1[0], @bool }; + } + + private static Task AcceptConnectionAsync(Socket server, string acceptMethod) + { + server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); + server.Listen(); + + switch (acceptMethod) + { + case "Sync": + return Task.Run(server.Accept); + + case "Task": + return server.AcceptAsync(); + + case "Apm": + return Task.Factory.FromAsync(server.BeginAccept, server.EndAccept, null); + + case "Eap": + var tcs = new TaskCompletionSource(); + var saea = new SocketAsyncEventArgs(); + + void Callback() + { + if (saea.SocketError == SocketError.Success) + { + tcs.SetResult(); + } + else + { + tcs.SetException(new SocketException((int)saea.SocketError)); + } + } + + saea.Completed += (_, __) => Callback(); + if (!server.AcceptAsync(saea)) + { + Callback(); + } + + return tcs.Task; + + default: + throw new ArgumentException(acceptMethod); + } + } + + private static async Task GetRemoteEndPointAsync(string useDnsEndPointString, int port) + { + const string Address = "microsoft.com"; + + if (bool.Parse(useDnsEndPointString)) + { + return new DnsEndPoint(Address, port); + } + else + { + IPAddress ip = (await Dns.GetHostAddressesAsync(Address))[0]; + return new IPEndPoint(ip, port); + } + } + + private static SocketHelperBase GetHelperBase(string socketMethod) + { + return socketMethod switch + { + "Sync" => new SocketHelperEap(), + "Task" => new SocketHelperTask(), + "Apm" => new SocketHelperApm(), + "Eap" => new SocketHelperEap(), + _ => throw new ArgumentException(socketMethod) + }; + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_Matrix_MemberData))] + public void EventSource_SocketConnectsLoopback_LogsConnectAcceptStartStop(string connectMethod, string acceptMethod) + { + RemoteExecutor.Invoke(async (connectMethod, acceptMethod) => + { + using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); + listener.AddActivityTracking(); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + + SocketHelperBase socketHelper = GetHelperBase(connectMethod); + + Task acceptTask = AcceptConnectionAsync(server, acceptMethod); + await WaitForEventAsync(events, "AcceptStart"); + + await socketHelper.ConnectAsync(client, server.LocalEndPoint); + await acceptTask; + + await WaitForEventAsync(events, "AcceptStop"); + await WaitForEventAsync(events, "ConnectStop"); + + await WaitForEventCountersAsync(events); + }); + Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + + VerifyStartStopEvents(events, connect: true, expectedCount: 1); + VerifyStartStopEvents(events, connect: false, expectedCount: 1); + + Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); + Assert.DoesNotContain(events, e => e.EventName == "AcceptFailed"); + + VerifyEventCounters(events, connectCount: 1); + }, connectMethod, acceptMethod).Dispose(); + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_WithBools_MemberData))] + public void EventSource_SocketConnectsRemote_LogsConnectStartStop(string connectMethod, bool useDnsEndPoint) + { + RemoteExecutor.Invoke(async (connectMethod, useDnsEndPointString) => + { + using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); + listener.AddActivityTracking(); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + + SocketHelperBase socketHelper = GetHelperBase(connectMethod); + + EndPoint endPoint = await GetRemoteEndPointAsync(useDnsEndPointString, port: 443); + await socketHelper.ConnectAsync(client, endPoint); + + await WaitForEventAsync(events, "ConnectStop"); + + await WaitForEventCountersAsync(events); + }); + Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + + VerifyStartStopEvents(events, connect: true, expectedCount: 1); + + Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); + + VerifyEventCounters(events, connectCount: 1, connectOnly: true); + }, connectMethod, useDnsEndPoint.ToString()).Dispose(); + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_WithBools_MemberData))] + public void EventSource_SocketConnectFailure_LogsConnectFailed(string connectMethod, bool useDnsEndPoint) + { + RemoteExecutor.Invoke(async (connectMethod, useDnsEndPointString) => + { + EndPoint endPoint = await GetRemoteEndPointAsync(useDnsEndPointString, port: 12345); + + using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); + listener.AddActivityTracking(); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + + SocketHelperBase socketHelper = GetHelperBase(connectMethod); + + await Assert.ThrowsAnyAsync(async () => + { + Task connectTask = socketHelper.ConnectAsync(client, endPoint); + await WaitForEventAsync(events, "ConnectStart"); + client.Dispose(); + await connectTask; + }); + + await WaitForEventAsync(events, "ConnectStop"); + + await WaitForEventCountersAsync(events); + }); + + VerifyConnectFailureEvents(events); + }, connectMethod, useDnsEndPoint.ToString()).Dispose(); + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_MemberData))] + public void EventSource_SocketAcceptFailure_LogsAcceptFailed(string acceptMethod) + { + RemoteExecutor.Invoke(async acceptMethod => + { + using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); + listener.AddActivityTracking(); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); + + await Assert.ThrowsAnyAsync(async () => + { + Task acceptTask = AcceptConnectionAsync(server, acceptMethod); + await WaitForEventAsync(events, "AcceptStart"); + server.Dispose(); + await acceptTask; + }); + + await WaitForEventAsync(events, "AcceptStop"); + + await WaitForEventCountersAsync(events); + }); + Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + + VerifyStartStopEvents(events, connect: false, expectedCount: 1); + + EventWrittenEventArgs failed = Assert.Single(events, e => e.EventName == "AcceptFailed"); + Assert.Equal(2, failed.Payload.Count); + Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); + Assert.Empty(failed.Payload[1] as string); + + EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "AcceptStart"); + Assert.Equal(start.ActivityId, failed.ActivityId); + + VerifyEventCounters(events, connectCount: 0); + }, acceptMethod).Dispose(); + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("Task", true)] + [InlineData("Task", false)] + [InlineData("Eap", true)] + [InlineData("Eap", false)] + public void EventSource_ConnectAsyncCanceled_LogsConnectCanceled(string connectMethod, bool useDnsEndPoint) + { + RemoteExecutor.Invoke(async (connectMethod, useDnsEndPointString) => + { + EndPoint endPoint = await GetRemoteEndPointAsync(useDnsEndPointString, port: 12345); + + using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); + listener.AddActivityTracking(); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + + await Assert.ThrowsAnyAsync(async () => + { + switch (connectMethod) + { + case "Task": + using (var cts = new CancellationTokenSource()) + { + ValueTask connectTask = client.ConnectAsync(endPoint, cts.Token); + await WaitForEventAsync(events, "ConnectStart"); + cts.Cancel(); + await connectTask; + } + break; + + case "Eap": + using (var saea = new SocketAsyncEventArgs()) + { + var tcs = new TaskCompletionSource(); + saea.RemoteEndPoint = endPoint; + saea.Completed += (_, __) => + { + Assert.NotEqual(SocketError.Success, saea.SocketError); + tcs.SetException(new SocketException((int)saea.SocketError)); + }; + Assert.True(client.ConnectAsync(saea)); + await WaitForEventAsync(events, "ConnectStart"); + Socket.CancelConnectAsync(saea); + await tcs.Task; + } + break; + } + }); + + await WaitForEventAsync(events, "ConnectStop"); + + await WaitForEventCountersAsync(events); + }); + + VerifyConnectFailureEvents(events); + }, connectMethod, useDnsEndPoint.ToString()).Dispose(); + } + + private static void VerifyConnectFailureEvents(ConcurrentQueue events) + { + Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + + VerifyStartStopEvents(events, connect: true, expectedCount: 1); + + EventWrittenEventArgs canceled = Assert.Single(events, e => e.EventName == "ConnectCanceled"); + Assert.Empty(canceled.Payload); + + EventWrittenEventArgs failed = Assert.Single(events, e => e.EventName == "ConnectFailed"); + Assert.Equal(2, failed.Payload.Count); + Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); + Assert.Empty(failed.Payload[1] as string); + + EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "ConnectStart"); + Assert.Equal(start.ActivityId, canceled.ActivityId); + Assert.Equal(start.ActivityId, failed.ActivityId); + + VerifyEventCounters(events, connectCount: 0); + } + [OuterLoop] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void EventSource_EventsRaisedAsExpected() { - RemoteExecutor.Invoke(() => + RemoteExecutor.Invoke(async () => { using (var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1)) { + listener.AddActivityTracking(); + var events = new ConcurrentQueue(); - listener.RunWithCallbackAsync(events.Enqueue, async () => + await listener.RunWithCallbackAsync(events.Enqueue, async () => { // Invoke several tests to execute code paths while tracing is enabled @@ -65,36 +399,99 @@ public void EventSource_EventsRaisedAsExpected() await new NetworkStreamTest().CopyToAsync_AllDataCopied(4096, true).ConfigureAwait(false); await new NetworkStreamTest().Timeout_ValidData_Roundtrips().ConfigureAwait(false); - await Task.Delay(300).ConfigureAwait(false); - }).Wait(); + + await WaitForEventCountersAsync(events); + }); Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself - VerifyEvents(events, "ConnectStart", 10); - VerifyEvents(events, "ConnectStop", 10); - - Dictionary eventCounters = events.Where(e => e.EventName == "EventCounters").Select(e => (IDictionary) e.Payload.Single()) - .GroupBy(d => (string)d["Name"], d => (double)d["Mean"], (k, v) => new { Name = k, Value = v.Sum() }) - .ToDictionary(p => p.Name, p => p.Value); - - VerifyEventCounter("incoming-connections-established", eventCounters); - VerifyEventCounter("outgoing-connections-established", eventCounters); - VerifyEventCounter("bytes-received", eventCounters); - VerifyEventCounter("bytes-sent", eventCounters); - VerifyEventCounter("datagrams-received", eventCounters); - VerifyEventCounter("datagrams-sent", eventCounters); + + VerifyStartStopEvents(events, connect: true, expectedCount: 10); + + Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); + + VerifyEventCounters(events, connectCount: 10, shouldHaveTransferedBytes: true, shouldHaveDatagrams: true); } }).Dispose(); } - private static void VerifyEvents(IEnumerable events, string eventName, int expectedCount) + private static void VerifyStartStopEvents(ConcurrentQueue events, bool connect, int expectedCount) { - EventWrittenEventArgs[] starts = events.Where(e => e.EventName == eventName).ToArray(); + string startName = connect ? "ConnectStart" : "AcceptStart"; + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == startName).ToArray(); Assert.Equal(expectedCount, starts.Length); + foreach (EventWrittenEventArgs start in starts) + { + object startPayload = Assert.Single(start.Payload); + Assert.False(string.IsNullOrWhiteSpace(startPayload as string)); + } + + string stopName = connect ? "ConnectStop" : "AcceptStop"; + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == stopName).ToArray(); + Assert.Equal(expectedCount, stops.Length); + Assert.All(stops, stop => Assert.Empty(stop.Payload)); + + for (int i = 0; i < expectedCount; i++) + { + Assert.NotEqual(Guid.Empty, starts[i].ActivityId); + Assert.Equal(starts[i].ActivityId, stops[i].ActivityId); + } } - private static void VerifyEventCounter(string name, Dictionary eventCounters) + private static async Task WaitForEventAsync(ConcurrentQueue events, string name) { - Assert.True(eventCounters.ContainsKey(name)); - Assert.True(eventCounters[name] > 0); + while (!events.Any(e => e.EventName == name)) + { + await Task.Delay(100); + } + } + + private static async Task WaitForEventCountersAsync(ConcurrentQueue events) + { + int startCount = events.Count; + + while (events.Skip(startCount).Count(e => e.EventName == "EventCounters") < 2) + { + await Task.Delay(100); + } + } + + private static void VerifyEventCounters(ConcurrentQueue events, int connectCount, bool connectOnly = false, bool shouldHaveTransferedBytes = false, bool shouldHaveDatagrams = false) + { + Dictionary eventCounters = events + .Where(e => e.EventName == "EventCounters") + .Select(e => (IDictionary)e.Payload.Single()) + .GroupBy(d => (string)d["Name"], d => (double)(d.ContainsKey("Mean") ? d["Mean"] : d["Increment"])) + .ToDictionary(p => p.Key, p => p.ToArray()); + + Assert.True(eventCounters.TryGetValue("outgoing-connections-established", out double[] outgoingConnections)); + Assert.Equal(connectCount, outgoingConnections[^1]); + + Assert.True(eventCounters.TryGetValue("incoming-connections-established", out double[] incomingConnections)); + Assert.Equal(connectOnly ? 0 : connectCount, incomingConnections[^1]); + + Assert.True(eventCounters.TryGetValue("bytes-received", out double[] bytesReceived)); + if (shouldHaveTransferedBytes) + { + Assert.True(bytesReceived[^1] > 0); + } + + Assert.True(eventCounters.TryGetValue("bytes-sent", out double[] bytesSent)); + if (shouldHaveTransferedBytes) + { + Assert.True(bytesSent[^1] > 0); + } + + Assert.True(eventCounters.TryGetValue("datagrams-received", out double[] datagramsReceived)); + if (shouldHaveDatagrams) + { + Assert.True(datagramsReceived[^1] > 0); + } + + Assert.True(eventCounters.TryGetValue("datagrams-sent", out double[] datagramsSent)); + if (shouldHaveDatagrams) + { + Assert.True(datagramsSent[^1] > 0); + } } } } From 5478d2e615c8540543083f248b68ee75d34f5ac9 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Mon, 14 Sep 2020 07:32:45 +0200 Subject: [PATCH 05/27] Avoid using value tuple in TestEventListener --- .../Diagnostics/Tracing/TestEventListener.cs | 22 ++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs index 820b37401581d..6d105540e6917 100644 --- a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs +++ b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs @@ -10,8 +10,14 @@ namespace System.Diagnostics.Tracing /// Simple event listener than invokes a callback for each event received. internal sealed class TestEventListener : EventListener { - private readonly Dictionary _names = new Dictionary(); - private readonly Dictionary _guids = new Dictionary(); + private class Settings + { + public EventLevel Level; + public EventKeywords Keywords; + } + + private readonly Dictionary _names = new Dictionary(); + private readonly Dictionary _guids = new Dictionary(); private readonly double? _eventCounterInterval; @@ -40,11 +46,17 @@ private void AddSource(string name, Guid? guid, EventLevel level, EventKeywords { lock (_eventSourceList) { + var settings = new Settings() + { + Level = level, + Keywords = keywords + }; + if (name is not null) - _names.Add(name, (level, keywords)); + _names.Add(name, settings); if (guid.HasValue) - _guids.Add(guid.Value, (level, keywords)); + _guids.Add(guid.Value, settings); foreach (EventSource source in _eventSourceList) { @@ -65,7 +77,7 @@ protected override void OnEventSourceCreated(EventSource eventSource) { _eventSourceList.Add(eventSource); - if (_names.TryGetValue(eventSource.Name, out (EventLevel Level, EventKeywords Keywords) settings) || + if (_names.TryGetValue(eventSource.Name, out Settings settings) || _guids.TryGetValue(eventSource.Guid, out settings)) { EnableEventSource(eventSource, settings.Level, settings.Keywords); From 46443e44b8bafca4d4347b86d8e4c798d0eca983 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 15 Sep 2020 05:15:46 +0200 Subject: [PATCH 06/27] Remove unnecessary argument to OnCompletedInternal --- .../System/Net/Sockets/SocketAsyncEventArgs.cs | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs index 23b159b4acf9d..aee77b115307d 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs @@ -198,14 +198,14 @@ public int BytesTransferred public event EventHandler? Completed; - private void OnCompletedInternal(SocketAsyncEventArgs e) + private void OnCompletedInternal() { if (SocketsTelemetry.Log.IsEnabled()) { - e.AfterConnectAcceptTelemetry(); + AfterConnectAcceptTelemetry(); } - OnCompleted(e); + OnCompleted(this); } protected virtual void OnCompleted(SocketAsyncEventArgs e) @@ -450,7 +450,7 @@ internal void SetResults(Exception exception, int bytesTransferred, SocketFlags private static void ExecutionCallback(object? state) { var thisRef = (SocketAsyncEventArgs)state!; - thisRef.OnCompletedInternal(thisRef); + thisRef.OnCompletedInternal(); } // Marks this object as no longer "in-use". Will also execute a Dispose deferred @@ -674,7 +674,7 @@ internal void FinishOperationAsyncFailure(SocketError socketError, int bytesTran if (context == null) { - OnCompletedInternal(this); + OnCompletedInternal(); } else { @@ -690,7 +690,7 @@ internal void FinishConnectByNameAsyncFailure(Exception exception, int bytesTran if (context == null) { - OnCompletedInternal(this); + OnCompletedInternal(); } else { @@ -711,7 +711,7 @@ internal void FinishWrapperConnectSuccess(Socket? connectSocket, int bytesTransf Complete(); if (context == null) { - OnCompletedInternal(this); + OnCompletedInternal(); } else { @@ -840,7 +840,7 @@ internal void FinishOperationAsyncSuccess(int bytesTransferred, SocketFlags flag // Raise completion event. if (context == null) { - OnCompletedInternal(this); + OnCompletedInternal(); } else { From 5d98405e112349b7a868f8706de8237cef21c3d3 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 15 Sep 2020 05:16:33 +0200 Subject: [PATCH 07/27] Remove redundant Telemetry.IsEnabled check --- .../Net/Sockets/SocketAsyncEventArgs.cs | 23 ++++++++----------- 1 file changed, 10 insertions(+), 13 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs index aee77b115307d..724fe31d9da08 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs @@ -215,21 +215,18 @@ protected virtual void OnCompleted(SocketAsyncEventArgs e) private void AfterConnectAcceptTelemetry() { - if (SocketsTelemetry.Log.IsEnabled()) + switch (LastOperation) { - switch (LastOperation) - { - case SocketAsyncOperation.Accept: - SocketsTelemetry.Log.AfterAccept(SocketError); - break; + case SocketAsyncOperation.Accept: + SocketsTelemetry.Log.AfterAccept(SocketError); + break; - case SocketAsyncOperation.Connect: - if (_multipleConnect is null) - { - SocketsTelemetry.Log.AfterConnect(SocketError); - } - break; - } + case SocketAsyncOperation.Connect: + if (_multipleConnect is null) + { + SocketsTelemetry.Log.AfterConnect(SocketError); + } + break; } } From b600f04ee7b906bd80c64ee4b17072d07fa5a710 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 15 Sep 2020 05:32:49 +0200 Subject: [PATCH 08/27] Log Connect/Accept start before the initial context capture --- .../src/System/Net/Sockets/Socket.cs | 10 +++++++++ .../Net/Sockets/SocketAsyncEventArgs.cs | 21 +++---------------- 2 files changed, 13 insertions(+), 18 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index 3ad0a656418c5..55e0c400e5af5 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -3676,6 +3676,11 @@ public bool AcceptAsync(SocketAsyncEventArgs e) SafeSocketHandle? acceptHandle; e.AcceptSocket = GetOrCreateAcceptSocket(e.AcceptSocket, true, "AcceptSocket", out acceptHandle); + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AcceptStart(_rightEndPoint!); + } + // Prepare for and make the native call. e.StartOperationCommon(this, SocketAsyncOperation.Accept); e.StartOperationAccept(); @@ -3776,6 +3781,11 @@ private bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket) _rightEndPoint = endPointSnapshot; } + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.ConnectStart(e._socketAddress!); + } + // Prepare for the native call. e.StartOperationCommon(this, SocketAsyncOperation.Connect); e.StartOperationConnect(multipleConnect: null, userSocket); diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs index 724fe31d9da08..2a40157b190a3 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs @@ -536,7 +536,9 @@ internal void StartOperationCommon(Socket? socket, SocketAsyncOperation operatio _currentSocket = socket; // Capture execution context if needed (it is unless explicitly disabled). - if (_flowExecutionContext) + // If Telemetry is enabled, make sure to capture the context if we're making a Connect or Accept call to preserve the activity + if (_flowExecutionContext || + (SocketsTelemetry.Log.IsEnabled() && (operation == SocketAsyncOperation.Connect || operation == SocketAsyncOperation.Accept))) { _context = ExecutionContext.Capture(); } @@ -574,14 +576,6 @@ internal void StartOperationAccept() _acceptBuffer = new byte[_acceptAddressBufferCount]; } } - - if (SocketsTelemetry.Log.IsEnabled()) - { - SocketsTelemetry.Log.AcceptStart(_currentSocket!._rightEndPoint!); - - // Ignore _flowExecutionContext when using Telemetry to avoid losing Activity tracking - _context = ExecutionContext.Capture(); - } } internal void StartOperationConnect(MultipleConnectAsync? multipleConnect, bool userSocket) @@ -589,15 +583,6 @@ internal void StartOperationConnect(MultipleConnectAsync? multipleConnect, bool _multipleConnect = multipleConnect; _connectSocket = null; _userSocket = userSocket; - - // Log only the actual connect operation to a remote endpoint. - if (SocketsTelemetry.Log.IsEnabled() && multipleConnect == null) - { - SocketsTelemetry.Log.ConnectStart(_socketAddress!); - - // Ignore _flowExecutionContext when using Telemetry to avoid losing Activity tracking - _context = ExecutionContext.Capture(); - } } internal void CancelConnectAsync() From 9a94dab4bac3e00a6b8f71f273390c1a7a481efd Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 15 Sep 2020 19:51:49 +0200 Subject: [PATCH 09/27] Use SocketHelperBase in Accept tests --- .../tests/FunctionalTests/TelemetryTest.cs | 58 +++---------------- 1 file changed, 8 insertions(+), 50 deletions(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index b82ab4f1de154..960e5a8951897 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -56,51 +56,6 @@ public static IEnumerable SocketMethods_WithBools_MemberData() select new[] { m1[0], @bool }; } - private static Task AcceptConnectionAsync(Socket server, string acceptMethod) - { - server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); - server.Listen(); - - switch (acceptMethod) - { - case "Sync": - return Task.Run(server.Accept); - - case "Task": - return server.AcceptAsync(); - - case "Apm": - return Task.Factory.FromAsync(server.BeginAccept, server.EndAccept, null); - - case "Eap": - var tcs = new TaskCompletionSource(); - var saea = new SocketAsyncEventArgs(); - - void Callback() - { - if (saea.SocketError == SocketError.Success) - { - tcs.SetResult(); - } - else - { - tcs.SetException(new SocketException((int)saea.SocketError)); - } - } - - saea.Completed += (_, __) => Callback(); - if (!server.AcceptAsync(saea)) - { - Callback(); - } - - return tcs.Task; - - default: - throw new ArgumentException(acceptMethod); - } - } - private static async Task GetRemoteEndPointAsync(string useDnsEndPointString, int port) { const string Address = "microsoft.com"; @@ -142,14 +97,15 @@ public void EventSource_SocketConnectsLoopback_LogsConnectAcceptStartStop(string await listener.RunWithCallbackAsync(events.Enqueue, async () => { using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); - using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); - SocketHelperBase socketHelper = GetHelperBase(connectMethod); + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); + server.Listen(); - Task acceptTask = AcceptConnectionAsync(server, acceptMethod); + Task acceptTask = GetHelperBase(acceptMethod).AcceptAsync(server); await WaitForEventAsync(events, "AcceptStart"); - await socketHelper.ConnectAsync(client, server.LocalEndPoint); + await GetHelperBase(connectMethod).ConnectAsync(client, server.LocalEndPoint); await acceptTask; await WaitForEventAsync(events, "AcceptStop"); @@ -255,10 +211,12 @@ public void EventSource_SocketAcceptFailure_LogsAcceptFailed(string acceptMethod await listener.RunWithCallbackAsync(events.Enqueue, async () => { using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); + server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); + server.Listen(); await Assert.ThrowsAnyAsync(async () => { - Task acceptTask = AcceptConnectionAsync(server, acceptMethod); + Task acceptTask = GetHelperBase(acceptMethod).AcceptAsync(server); await WaitForEventAsync(events, "AcceptStart"); server.Dispose(); await acceptTask; From eb9220d1ff69d901eb45523198194f5ea7c292e1 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Wed, 16 Sep 2020 18:39:26 +0200 Subject: [PATCH 10/27] Avoid duplicate events for BeginConnect without ConnextEx support --- .../src/System/Net/Sockets/Socket.cs | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index 55e0c400e5af5..05826751099d0 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -2136,14 +2136,6 @@ private bool CanUseConnectEx(EndPoint remoteEP) internal IAsyncResult UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback? callback, object? state, bool flowContext = false) { - if (SocketsTelemetry.Log.IsEnabled()) - { - SocketsTelemetry.Log.ConnectStart(remoteEP); - - // Ignore flowContext when using Telemetry to avoid losing Activity tracking - flowContext = true; - } - if (CanUseConnectEx(remoteEP)) { return BeginConnectEx(remoteEP, flowContext, callback, state); @@ -2367,7 +2359,7 @@ public void EndConnect(IAsyncResult asyncResult) { if (Disposed) { - if (SocketsTelemetry.Log.IsEnabled() && asyncResult is not MultipleAddressConnectAsyncResult) + if (SocketsTelemetry.Log.IsEnabled() && asyncResult is ConnectOverlappedAsyncResult) { SocketsTelemetry.Log.AfterConnect(SocketError.OperationAborted); } @@ -2402,7 +2394,7 @@ asyncResult as MultipleAddressConnectAsyncResult ?? Exception? ex = castedAsyncResult.Result as Exception; - if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is not MultipleAddressConnectAsyncResult) + if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is ConnectOverlappedAsyncResult) { SocketsTelemetry.Log.AfterConnect((SocketError)castedAsyncResult.ErrorCode, ex?.Message); } @@ -4636,6 +4628,14 @@ internal void InternalSetBlocking(bool desired) // Since this is private, the unsafe mode is specified with a flag instead of an overload. private IAsyncResult BeginConnectEx(EndPoint remoteEP, bool flowContext, AsyncCallback? callback, object? state) { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.ConnectStart(remoteEP); + + // Ignore flowContext when using Telemetry to avoid losing Activity tracking + flowContext = true; + } + EndPoint endPointSnapshot = remoteEP; Internals.SocketAddress socketAddress = Serialize(ref endPointSnapshot); From bb4ae17384df51018397eaf3452cd4116055ec7c Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Wed, 16 Sep 2020 18:53:11 +0200 Subject: [PATCH 11/27] Enable Sync Socket tests --- .../src/System/Net/Sockets/SocketsTelemetry.cs | 2 +- .../System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index 0293707fc0609..19ae23786a023 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -111,7 +111,7 @@ public void AfterConnect(SocketError error, string? exceptionMessage = null) } else { - if (error == SocketError.OperationAborted) + if (error == SocketError.OperationAborted || error == SocketError.Interrupted) { ConnectCanceled(); } diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 960e5a8951897..97f346c1327a5 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -75,7 +75,7 @@ private static SocketHelperBase GetHelperBase(string socketMethod) { return socketMethod switch { - "Sync" => new SocketHelperEap(), + "Sync" => new SocketHelperArraySync(), "Task" => new SocketHelperTask(), "Apm" => new SocketHelperApm(), "Eap" => new SocketHelperEap(), From c315bc2eec39ba42920159c87bece278067a2220 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Wed, 16 Sep 2020 21:03:26 +0200 Subject: [PATCH 12/27] Revert unrelated SocketPal change --- .../src/System/Net/Sockets/SocketPal.Windows.cs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs index 137c1377fd368..1d7947523b12e 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketPal.Windows.cs @@ -1304,6 +1304,7 @@ public static unsafe SocketError AcceptAsync(Socket socket, SafeSocketHandle han try { // This can throw ObjectDisposedException. + int bytesTransferred; bool success = socket.AcceptEx( handle, acceptHandle, @@ -1311,10 +1312,10 @@ public static unsafe SocketError AcceptAsync(Socket socket, SafeSocketHandle han receiveSize, addressBufferSize, addressBufferSize, - out int bytesReceived, + out bytesTransferred, asyncResult.DangerousOverlappedPointer); // SafeHandle was just created in SetUnmanagedStructures - return asyncResult.ProcessOverlappedResult(success, bytesReceived); + return asyncResult.ProcessOverlappedResult(success, 0); } catch { From 2f62c7fde9a184738fa09878b0a73a9ed778d010 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 00:22:43 +0200 Subject: [PATCH 13/27] Log the correct ErrorCode in case of socket disposal --- .../src/System/Net/Sockets/Socket.cs | 29 ++++++++++++------- .../System/Net/Sockets/SocketsTelemetry.cs | 2 +- 2 files changed, 20 insertions(+), 11 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index 05826751099d0..f3f65073ee510 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -2361,7 +2361,7 @@ public void EndConnect(IAsyncResult asyncResult) { if (SocketsTelemetry.Log.IsEnabled() && asyncResult is ConnectOverlappedAsyncResult) { - SocketsTelemetry.Log.AfterConnect(SocketError.OperationAborted); + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket); } ThrowObjectDisposedException(); @@ -2394,16 +2394,12 @@ asyncResult as MultipleAddressConnectAsyncResult ?? Exception? ex = castedAsyncResult.Result as Exception; - if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is ConnectOverlappedAsyncResult) - { - SocketsTelemetry.Log.AfterConnect((SocketError)castedAsyncResult.ErrorCode, ex?.Message); - } - if (ex != null || (SocketError)castedAsyncResult.ErrorCode != SocketError.Success) { + SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode; + if (ex == null) { - SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode; UpdateConnectSocketErrorForDisposed(ref errorCode); // Update the internal state of this socket according to the error before throwing. SocketException se = SocketExceptionFactory.CreateSocketException((int)errorCode, castedAsyncResult.RemoteEndPoint); @@ -2411,10 +2407,20 @@ asyncResult as MultipleAddressConnectAsyncResult ?? ex = se; } + if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is ConnectOverlappedAsyncResult) + { + SocketsTelemetry.Log.AfterConnect(errorCode, ex.Message); + } + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(this, ex); ExceptionDispatchInfo.Throw(ex); } + if (SocketsTelemetry.Log.IsEnabled() && castedAsyncResult is ConnectOverlappedAsyncResult) + { + SocketsTelemetry.Log.AfterConnect(SocketError.Success); + } + if (NetEventSource.Log.IsEnabled()) NetEventSource.Connected(this, LocalEndPoint, RemoteEndPoint); } @@ -3577,7 +3583,7 @@ private Socket EndAcceptCommon(out byte[]? buffer, out int bytesTransferred, IAs { if (Disposed) { - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(SocketError.OperationAborted); + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(SocketError.Interrupted); ThrowObjectDisposedException(); } @@ -4239,8 +4245,6 @@ private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socket SocketError errorCode = SocketPal.Connect(_handle, socketAddress.Buffer, socketAddress.Size); - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterConnect(errorCode); - // Throw an appropriate SocketException if the native call fails. if (errorCode != SocketError.Success) { @@ -4249,9 +4253,14 @@ private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socket SocketException socketException = SocketExceptionFactory.CreateSocketException((int)errorCode, endPointSnapshot); UpdateStatusAfterSocketError(socketException); if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(this, socketException); + + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterConnect(errorCode); + throw socketException; } + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterConnect(SocketError.Success); + if (_rightEndPoint == null) { // Save a copy of the EndPoint so we can use it for Create(). diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index 19ae23786a023..b2ceb164993af 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -111,7 +111,7 @@ public void AfterConnect(SocketError error, string? exceptionMessage = null) } else { - if (error == SocketError.OperationAborted || error == SocketError.Interrupted) + if (error == SocketError.OperationAborted || error == SocketError.NotSocket) { ConnectCanceled(); } From c7378a900d2ca312c3477afc0bbca88584af1530 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 04:37:08 +0200 Subject: [PATCH 14/27] Add more info on TelemetryTest timeout --- .../System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 97f346c1327a5..c3c8875749181 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -397,8 +397,12 @@ private static void VerifyStartStopEvents(ConcurrentQueue private static async Task WaitForEventAsync(ConcurrentQueue events, string name) { + DateTime startTime = DateTime.UtcNow; while (!events.Any(e => e.EventName == name)) { + if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30)) + throw new TimeoutException($"Timed out waiting for {name}"); + await Task.Delay(100); } } From 1f8530cfaa4fd58b5eddae67004b930cc2da9c34 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 13:02:37 +0200 Subject: [PATCH 15/27] Add PlatformSpecific attribute to ConnectFailure test --- .../System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index c3c8875749181..28301fbabf674 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -163,6 +163,7 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [PlatformSpecific(~(TestPlatforms.OSX | TestPlatforms.FreeBSD))] // Same as Connect.ConnectGetsCanceledByDispose [MemberData(nameof(SocketMethods_WithBools_MemberData))] public void EventSource_SocketConnectFailure_LogsConnectFailed(string connectMethod, bool useDnsEndPoint) { From 3cf62208f7b7f81ddcb4f7ea5b729800fb487a67 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 13:31:56 +0200 Subject: [PATCH 16/27] Add missing BeginConnect AfterConnect call on sync failure --- .../src/System/Net/Sockets/Socket.cs | 10 ++++++---- .../src/System/Net/Sockets/SocketsTelemetry.cs | 9 --------- 2 files changed, 6 insertions(+), 13 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index f3f65073ee510..523e8a47fd354 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -4637,17 +4637,17 @@ internal void InternalSetBlocking(bool desired) // Since this is private, the unsafe mode is specified with a flag instead of an overload. private IAsyncResult BeginConnectEx(EndPoint remoteEP, bool flowContext, AsyncCallback? callback, object? state) { + EndPoint endPointSnapshot = remoteEP; + Internals.SocketAddress socketAddress = Serialize(ref endPointSnapshot); + if (SocketsTelemetry.Log.IsEnabled()) { - SocketsTelemetry.Log.ConnectStart(remoteEP); + SocketsTelemetry.Log.ConnectStart(socketAddress); // Ignore flowContext when using Telemetry to avoid losing Activity tracking flowContext = true; } - EndPoint endPointSnapshot = remoteEP; - Internals.SocketAddress socketAddress = Serialize(ref endPointSnapshot); - WildcardBindForConnectIfNecessary(endPointSnapshot.AddressFamily); // Allocate the async result and the event we'll pass to the thread pool. @@ -4693,6 +4693,8 @@ private IAsyncResult BeginConnectEx(EndPoint remoteEP, bool flowContext, AsyncCa _rightEndPoint = oldEndPoint; _localEndPoint = null; + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterConnect(errorCode); + throw new SocketException((int)errorCode); } diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index b2ceb164993af..5957cd647fe19 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -92,15 +92,6 @@ public void ConnectStart(Internals.SocketAddress address) } } - [NonEvent] - public void ConnectStart(EndPoint address) - { - if (IsEnabled(EventLevel.Informational, EventKeywords.All)) - { - ConnectStart(address.ToString()); - } - } - [NonEvent] public void AfterConnect(SocketError error, string? exceptionMessage = null) { From 13480c206d5bb6e2664cc5ef8a0cf94025dd6edd Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 13:41:42 +0200 Subject: [PATCH 17/27] Add comment around GetHelperBase --- .../System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 28301fbabf674..7694b2731f485 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -71,6 +71,8 @@ private static async Task GetRemoteEndPointAsync(string useDnsEndPoint } } + // RemoteExecutor only supports simple argument types such as strings + // That's why we use this helper method instead of returning SocketHelperBases from MemberDatas directly private static SocketHelperBase GetHelperBase(string socketMethod) { return socketMethod switch From ce797acb460db4227023f757f6433d7a41fa547c Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 17 Sep 2020 18:59:43 +0200 Subject: [PATCH 18/27] Correct WaitForEventCountersAsync helper --- .../tests/FunctionalTests/TelemetryTest.cs | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 7694b2731f485..6bfce8bcd3ca6 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -414,10 +414,20 @@ private static async Task WaitForEventCountersAsync(ConcurrentQueue e.EventName == "EventCounters") < 2) + while (events.Skip(startCount).Count(IsBytesSentEventCounter) < 2) { await Task.Delay(100); } + + static bool IsBytesSentEventCounter(EventWrittenEventArgs e) + { + if (e.EventName != "EventCounters") + return false; + + var dictionary = (IDictionary)e.Payload.Single(); + + return (string)dictionary["Name"] == "bytes-sent"; + } } private static void VerifyEventCounters(ConcurrentQueue events, int connectCount, bool connectOnly = false, bool shouldHaveTransferedBytes = false, bool shouldHaveDatagrams = false) From 6120452a1be935a8bfd8458b448283207d8ed142 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 18 Sep 2020 08:04:00 +0200 Subject: [PATCH 19/27] Assert against SocketError.TimedOut in ConnectFailed test --- .../tests/FunctionalTests/TelemetryTest.cs | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 6bfce8bcd3ca6..bc5f1c18ce2b6 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -99,11 +99,11 @@ public void EventSource_SocketConnectsLoopback_LogsConnectAcceptStartStop(string await listener.RunWithCallbackAsync(events.Enqueue, async () => { using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); - - using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); server.Listen(); + using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); + Task acceptTask = GetHelperBase(acceptMethod).AcceptAsync(server); await WaitForEventAsync(events, "AcceptStart"); @@ -183,7 +183,7 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => SocketHelperBase socketHelper = GetHelperBase(connectMethod); - await Assert.ThrowsAnyAsync(async () => + Exception ex = await Assert.ThrowsAnyAsync(async () => { Task connectTask = socketHelper.ConnectAsync(client, endPoint); await WaitForEventAsync(events, "ConnectStart"); @@ -191,6 +191,11 @@ await Assert.ThrowsAnyAsync(async () => await connectTask; }); + if (ex is SocketException se) + { + Assert.NotEqual(SocketError.TimedOut, se.SocketErrorCode); + } + await WaitForEventAsync(events, "ConnectStop"); await WaitForEventCountersAsync(events); From 4d0289f54624196ac40ca8bf99f5925ce3baafa4 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 18 Sep 2020 16:21:43 +0200 Subject: [PATCH 20/27] Add EndConnect comment --- .../System.Net.Sockets/src/System/Net/Sockets/Socket.cs | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index 523e8a47fd354..8ffa29ac71733 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -2357,6 +2357,14 @@ public void Disconnect(bool reuseSocket) // int - Return code from async Connect, 0 for success, SocketError.NotConnected otherwise public void EndConnect(IAsyncResult asyncResult) { + // There are three AsyncResult types we support in EndConnect: + // - ConnectAsyncResult - a fully synchronous operation that already completed, wrapped in an AsyncResult + // - MultipleAddressConnectAsyncResult - a parent operation for other Connects (connecting to DnsEndPoint) + // - ConnectOverlappedAsyncResult - a connect to an IPEndPoint + // For Telemetry, we already logged everything for ConnectAsyncResult in DoConnect, + // and we want to avoid logging duplicated events for MultipleAddressConnect. + // Therefore, we always check that asyncResult is ConnectOverlapped before logging. + if (Disposed) { if (SocketsTelemetry.Log.IsEnabled() && asyncResult is ConnectOverlappedAsyncResult) From 3dd524ef85e7f7fc0a85ad75c4f90b91802046da Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 18 Sep 2020 17:41:42 +0200 Subject: [PATCH 21/27] Log Failure around sync SocketPal exceptions --- .../src/System/Net/Sockets/Socket.cs | 98 +++++++++++++++---- .../tests/FunctionalTests/TelemetryTest.cs | 4 + 2 files changed, 82 insertions(+), 20 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index 8ffa29ac71733..b0011fa95a38f 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -1104,22 +1104,38 @@ public Socket Accept() // This may throw ObjectDisposedException. SafeSocketHandle acceptedSocketHandle; - SocketError errorCode = SocketPal.Accept( - _handle, - socketAddress.Buffer, - ref socketAddress.InternalSize, - out acceptedSocketHandle); + SocketError errorCode; + try + { + errorCode = SocketPal.Accept( + _handle, + socketAddress.Buffer, + ref socketAddress.InternalSize, + out acceptedSocketHandle); + } + catch (Exception ex) + { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterAccept(SocketError.Interrupted, ex.Message); + } - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); + throw; + } // Throw an appropriate SocketException if the native call fails. if (errorCode != SocketError.Success) { Debug.Assert(acceptedSocketHandle.IsInvalid); UpdateAcceptSocketErrorForDisposed(ref errorCode); + + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); + UpdateStatusAfterSocketErrorAndThrowException(errorCode); } + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(SocketError.Success); + Debug.Assert(!acceptedSocketHandle.IsInvalid); Socket socket = CreateAcceptSocket(acceptedSocketHandle, _rightEndPoint.Create(socketAddress)); @@ -3551,16 +3567,30 @@ private IAsyncResult BeginAcceptCommon(Socket? acceptSocket, int receiveSize, As if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStart(_rightEndPoint); int socketAddressSize = GetAddressSize(_rightEndPoint); - SocketError errorCode = SocketPal.AcceptAsync(this, _handle, acceptHandle, receiveSize, socketAddressSize, asyncResult); + SocketError errorCode; + try + { + errorCode = SocketPal.AcceptAsync(this, _handle, acceptHandle, receiveSize, socketAddressSize, asyncResult); + } + catch (Exception ex) + { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterAccept(SocketError.Interrupted, ex.Message); + } + + throw; + } if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"AcceptAsync returns:{errorCode} {asyncResult}"); // Throw an appropriate SocketException if the native call fails synchronously. if (!CheckErrorAndUpdateStatus(errorCode)) { + UpdateAcceptSocketErrorForDisposed(ref errorCode); + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); - UpdateAcceptSocketErrorForDisposed(ref errorCode); throw new SocketException((int)errorCode); } @@ -3622,14 +3652,17 @@ private Socket EndAcceptCommon(out byte[]? buffer, out int bytesTransferred, IAs // Throw an appropriate SocketException if the native call failed asynchronously. SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode; - if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); - if (errorCode != SocketError.Success) { UpdateAcceptSocketErrorForDisposed(ref errorCode); + + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(errorCode); + UpdateStatusAfterSocketErrorAndThrowException(errorCode); } + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AfterAccept(SocketError.Success); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Accepted(socket, socket.RemoteEndPoint, socket.LocalEndPoint); return socket; } @@ -3682,21 +3715,23 @@ public bool AcceptAsync(SocketAsyncEventArgs e) SafeSocketHandle? acceptHandle; e.AcceptSocket = GetOrCreateAcceptSocket(e.AcceptSocket, true, "AcceptSocket", out acceptHandle); - if (SocketsTelemetry.Log.IsEnabled()) - { - SocketsTelemetry.Log.AcceptStart(_rightEndPoint!); - } + if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.AcceptStart(_rightEndPoint!); // Prepare for and make the native call. e.StartOperationCommon(this, SocketAsyncOperation.Accept); e.StartOperationAccept(); - SocketError socketError = SocketError.Success; + SocketError socketError; try { socketError = e.DoOperationAccept(this, _handle, acceptHandle); } - catch + catch (Exception ex) { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterAccept(SocketError.Interrupted, ex.Message); + } + // Clear in-use flag on event args object. e.Complete(); throw; @@ -3797,7 +3832,7 @@ private bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket) e.StartOperationConnect(multipleConnect: null, userSocket); // Make the native call. - SocketError socketError = SocketError.Success; + SocketError socketError; try { if (CanUseConnectEx(endPointSnapshot)) @@ -3810,8 +3845,13 @@ private bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket) socketError = e.DoOperationConnect(this, _handle); } } - catch + catch (Exception ex) { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + } + _rightEndPoint = oldEndPoint; _localEndPoint = null; @@ -4251,7 +4291,20 @@ private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socket { if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStart(socketAddress); - SocketError errorCode = SocketPal.Connect(_handle, socketAddress.Buffer, socketAddress.Size); + SocketError errorCode; + try + { + errorCode = SocketPal.Connect(_handle, socketAddress.Buffer, socketAddress.Size); + } + catch (Exception ex) + { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + } + + throw; + } // Throw an appropriate SocketException if the native call fails. if (errorCode != SocketError.Success) @@ -4678,8 +4731,13 @@ private IAsyncResult BeginConnectEx(EndPoint remoteEP, bool flowContext, AsyncCa { errorCode = SocketPal.ConnectAsync(this, _handle, socketAddress.Buffer, socketAddress.Size, asyncResult); } - catch + catch (Exception ex) { + if (SocketsTelemetry.Log.IsEnabled()) + { + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + } + // _rightEndPoint will always equal oldEndPoint. _rightEndPoint = oldEndPoint; _localEndPoint = null; diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index bc5f1c18ce2b6..09688ddc23f0a 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -417,10 +417,14 @@ private static async Task WaitForEventAsync(ConcurrentQueue events) { + DateTime startTime = DateTime.UtcNow; int startCount = events.Count; while (events.Skip(startCount).Count(IsBytesSentEventCounter) < 2) { + if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30)) + throw new TimeoutException($"Timed out waiting for EventCounters"); + await Task.Delay(100); } From fabbea71ad5c1df35b703e890f32b87135bf0c16 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 22 Sep 2020 18:16:30 +0200 Subject: [PATCH 22/27] Don't assert that the exception message is empty --- .../System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 09688ddc23f0a..886ccc7e9deaa 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -241,7 +241,7 @@ await Assert.ThrowsAnyAsync(async () => EventWrittenEventArgs failed = Assert.Single(events, e => e.EventName == "AcceptFailed"); Assert.Equal(2, failed.Payload.Count); Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); - Assert.Empty(failed.Payload[1] as string); + Assert.IsType(failed.Payload[1]); EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "AcceptStart"); Assert.Equal(start.ActivityId, failed.ActivityId); @@ -324,7 +324,7 @@ private static void VerifyConnectFailureEvents(ConcurrentQueue e.EventName == "ConnectFailed"); Assert.Equal(2, failed.Payload.Count); Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); - Assert.Empty(failed.Payload[1] as string); + Assert.IsType(failed.Payload[1]); EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "ConnectStart"); Assert.Equal(start.ActivityId, canceled.ActivityId); From 2ac2bc7f15985aa6bcd82d257a183941f6dd69fc Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Tue, 22 Sep 2020 20:50:03 +0200 Subject: [PATCH 23/27] Dispose socket in a different Thread --- .../tests/FunctionalTests/TelemetryTest.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 886ccc7e9deaa..90cc3cb3baebb 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -187,8 +187,8 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => { Task connectTask = socketHelper.ConnectAsync(client, endPoint); await WaitForEventAsync(events, "ConnectStart"); - client.Dispose(); - await connectTask; + Task disposeTask = Task.Run(() => client.Dispose()); + await new[] { connectTask, disposeTask }.WhenAllOrAnyFailed(); }); if (ex is SocketException se) @@ -226,8 +226,8 @@ await Assert.ThrowsAnyAsync(async () => { Task acceptTask = GetHelperBase(acceptMethod).AcceptAsync(server); await WaitForEventAsync(events, "AcceptStart"); - server.Dispose(); - await acceptTask; + Task disposeTask = Task.Run(() => server.Dispose()); + await new[] { acceptTask, disposeTask }.WhenAllOrAnyFailed(); }); await WaitForEventAsync(events, "AcceptStop"); From d0d849f89231b68f8a592d25ae24eda321f4f770 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 24 Sep 2020 18:19:48 +0200 Subject: [PATCH 24/27] Disable Telemetry failure tests for Sync on RedHat7 --- .../tests/FunctionalTests/TelemetryTest.cs | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 90cc3cb3baebb..fab61bd9a2056 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -8,6 +8,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.DotNet.RemoteExecutor; +using Microsoft.DotNet.XUnitExtensions; using Xunit; using Xunit.Abstractions; @@ -169,6 +170,12 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => [MemberData(nameof(SocketMethods_WithBools_MemberData))] public void EventSource_SocketConnectFailure_LogsConnectFailed(string connectMethod, bool useDnsEndPoint) { + if (connectMethod == "Sync" && PlatformDetection.IsRedHatFamily7) + { + // [ActiveIssue("https://github.com/dotnet/runtime/issues/42686")] + throw new SkipTestException("Disposing a Socket performing a sync operation can hang on RedHat7 systems"); + } + RemoteExecutor.Invoke(async (connectMethod, useDnsEndPointString) => { EndPoint endPoint = await GetRemoteEndPointAsync(useDnsEndPointString, port: 12345); @@ -210,6 +217,12 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => [MemberData(nameof(SocketMethods_MemberData))] public void EventSource_SocketAcceptFailure_LogsAcceptFailed(string acceptMethod) { + if (acceptMethod == "Sync" && PlatformDetection.IsRedHatFamily7) + { + // [ActiveIssue("https://github.com/dotnet/runtime/issues/42686")] + throw new SkipTestException("Disposing a Socket performing a sync operation can hang on RedHat7 systems"); + } + RemoteExecutor.Invoke(async acceptMethod => { using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); From 1b9d10ae5eca7ab1993b6dbf08f2e556bdf34ac4 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 24 Sep 2020 23:24:41 +0200 Subject: [PATCH 25/27] Use more descriptive names in MemberData generation --- .../tests/FunctionalTests/TelemetryTest.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index fab61bd9a2056..7e6a84b890083 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -45,16 +45,16 @@ public static IEnumerable SocketMethods_MemberData() public static IEnumerable SocketMethods_Matrix_MemberData() { - return from m1 in SocketMethods_MemberData() - from m2 in SocketMethods_MemberData() - select new[] { m1[0], m2[0] }; + return from connectMethod in SocketMethods_MemberData() + from acceptMethod in SocketMethods_MemberData() + select new[] { connectMethod[0], acceptMethod[0] }; } public static IEnumerable SocketMethods_WithBools_MemberData() { - return from m1 in SocketMethods_MemberData() - from @bool in new[] { true, false } - select new[] { m1[0], @bool }; + return from connectMethod in SocketMethods_MemberData() + from useDnsEndPoint in new[] { true, false } + select new[] { connectMethod[0], useDnsEndPoint }; } private static async Task GetRemoteEndPointAsync(string useDnsEndPointString, int port) From a39d49b330d316fd796011c23c77576ba1306566 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 25 Sep 2020 00:58:32 +0200 Subject: [PATCH 26/27] Avoid using reflection for #42128 workaround --- .../Diagnostics/Tracing/TestEventListener.cs | 7 -- .../tests/FunctionalTests/TelemetryTest.cs | 106 +++++++++--------- 2 files changed, 53 insertions(+), 60 deletions(-) diff --git a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs index 6d105540e6917..74c0d9fa9395a 100644 --- a/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs +++ b/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs @@ -2,7 +2,6 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Collections.Generic; -using System.Reflection; using System.Threading.Tasks; namespace System.Diagnostics.Tracing @@ -111,14 +110,8 @@ public async Task RunWithCallbackAsync(Action handler, Fu finally { _eventWritten = null; } } - // Workaround for being able to inspect the ActivityId property after storing EventWrittenEventArgs - // [ActiveIssue("https://github.com/dotnet/runtime/issues/42128")] - private static readonly FieldInfo s_activityIdFieldInfo = - typeof(EventWrittenEventArgs).GetField("m_activityId", BindingFlags.NonPublic | BindingFlags.Instance); - protected override void OnEventWritten(EventWrittenEventArgs eventData) { - s_activityIdFieldInfo.SetValue(eventData, eventData.ActivityId); _eventWritten?.Invoke(eventData); } } diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 7e6a84b890083..59a7955efe8c1 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -96,8 +96,8 @@ public void EventSource_SocketConnectsLoopback_LogsConnectAcceptStartStop(string using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); @@ -116,14 +116,14 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => await WaitForEventCountersAsync(events); }); - Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself VerifyStartStopEvents(events, connect: true, expectedCount: 1); VerifyStartStopEvents(events, connect: false, expectedCount: 1); - Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); - Assert.DoesNotContain(events, e => e.EventName == "AcceptFailed"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); + Assert.DoesNotContain(events, e => e.Event.EventName == "AcceptFailed"); VerifyEventCounters(events, connectCount: 1); }, connectMethod, acceptMethod).Dispose(); @@ -139,8 +139,8 @@ public void EventSource_SocketConnectsRemote_LogsConnectStartStop(string connect using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); @@ -153,12 +153,12 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => await WaitForEventCountersAsync(events); }); - Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself VerifyStartStopEvents(events, connect: true, expectedCount: 1); - Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); VerifyEventCounters(events, connectCount: 1, connectOnly: true); }, connectMethod, useDnsEndPoint.ToString()).Dispose(); @@ -183,8 +183,8 @@ public void EventSource_SocketConnectFailure_LogsConnectFailed(string connectMet using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); @@ -228,8 +228,8 @@ public void EventSource_SocketAcceptFailure_LogsAcceptFailed(string acceptMethod using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { using var server = new Socket(SocketType.Stream, ProtocolType.Tcp); server.Bind(new IPEndPoint(IPAddress.Loopback, 0)); @@ -247,17 +247,17 @@ await Assert.ThrowsAnyAsync(async () => await WaitForEventCountersAsync(events); }); - Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself VerifyStartStopEvents(events, connect: false, expectedCount: 1); - EventWrittenEventArgs failed = Assert.Single(events, e => e.EventName == "AcceptFailed"); - Assert.Equal(2, failed.Payload.Count); - Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); - Assert.IsType(failed.Payload[1]); + (EventWrittenEventArgs Event, Guid ActivityId) failed = Assert.Single(events, e => e.Event.EventName == "AcceptFailed"); + Assert.Equal(2, failed.Event.Payload.Count); + Assert.True(Enum.IsDefined((SocketError)failed.Event.Payload[0])); + Assert.IsType(failed.Event.Payload[1]); - EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "AcceptStart"); - Assert.Equal(start.ActivityId, failed.ActivityId); + (_, Guid startActivityId) = Assert.Single(events, e => e.Event.EventName == "AcceptStart"); + Assert.Equal(startActivityId, failed.ActivityId); VerifyEventCounters(events, connectCount: 0); }, acceptMethod).Dispose(); @@ -278,8 +278,8 @@ public void EventSource_ConnectAsyncCanceled_LogsConnectCanceled(string connectM using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1); listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { using var client = new Socket(SocketType.Stream, ProtocolType.Tcp); @@ -325,23 +325,23 @@ await Assert.ThrowsAnyAsync(async () => }, connectMethod, useDnsEndPoint.ToString()).Dispose(); } - private static void VerifyConnectFailureEvents(ConcurrentQueue events) + private static void VerifyConnectFailureEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events) { - Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself VerifyStartStopEvents(events, connect: true, expectedCount: 1); - EventWrittenEventArgs canceled = Assert.Single(events, e => e.EventName == "ConnectCanceled"); - Assert.Empty(canceled.Payload); + (EventWrittenEventArgs Event, Guid ActivityId) canceled = Assert.Single(events, e => e.Event.EventName == "ConnectCanceled"); + Assert.Empty(canceled.Event.Payload); - EventWrittenEventArgs failed = Assert.Single(events, e => e.EventName == "ConnectFailed"); - Assert.Equal(2, failed.Payload.Count); - Assert.True(Enum.IsDefined((SocketError)failed.Payload[0])); - Assert.IsType(failed.Payload[1]); + (EventWrittenEventArgs Event, Guid ActivityId) failed = Assert.Single(events, e => e.Event.EventName == "ConnectFailed"); + Assert.Equal(2, failed.Event.Payload.Count); + Assert.True(Enum.IsDefined((SocketError)failed.Event.Payload[0])); + Assert.IsType(failed.Event.Payload[1]); - EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "ConnectStart"); - Assert.Equal(start.ActivityId, canceled.ActivityId); - Assert.Equal(start.ActivityId, failed.ActivityId); + (_, Guid startActivityId) = Assert.Single(events, e => e.Event.EventName == "ConnectStart"); + Assert.Equal(startActivityId, canceled.ActivityId); + Assert.Equal(startActivityId, failed.ActivityId); VerifyEventCounters(events, connectCount: 0); } @@ -356,8 +356,8 @@ public void EventSource_EventsRaisedAsExpected() { listener.AddActivityTracking(); - var events = new ConcurrentQueue(); - await listener.RunWithCallbackAsync(events.Enqueue, async () => + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => { // Invoke several tests to execute code paths while tracing is enabled @@ -381,33 +381,33 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => await WaitForEventCountersAsync(events); }); - Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself VerifyStartStopEvents(events, connect: true, expectedCount: 10); - Assert.DoesNotContain(events, e => e.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.EventName == "ConnectCanceled"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); + Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); VerifyEventCounters(events, connectCount: 10, shouldHaveTransferedBytes: true, shouldHaveDatagrams: true); } }).Dispose(); } - private static void VerifyStartStopEvents(ConcurrentQueue events, bool connect, int expectedCount) + private static void VerifyStartStopEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, bool connect, int expectedCount) { string startName = connect ? "ConnectStart" : "AcceptStart"; - EventWrittenEventArgs[] starts = events.Where(e => e.EventName == startName).ToArray(); + (EventWrittenEventArgs Event, Guid ActivityId)[] starts = events.Where(e => e.Event.EventName == startName).ToArray(); Assert.Equal(expectedCount, starts.Length); - foreach (EventWrittenEventArgs start in starts) + foreach ((EventWrittenEventArgs Event, _) in starts) { - object startPayload = Assert.Single(start.Payload); + object startPayload = Assert.Single(Event.Payload); Assert.False(string.IsNullOrWhiteSpace(startPayload as string)); } string stopName = connect ? "ConnectStop" : "AcceptStop"; - EventWrittenEventArgs[] stops = events.Where(e => e.EventName == stopName).ToArray(); + (EventWrittenEventArgs Event, Guid ActivityId)[] stops = events.Where(e => e.Event.EventName == stopName).ToArray(); Assert.Equal(expectedCount, stops.Length); - Assert.All(stops, stop => Assert.Empty(stop.Payload)); + Assert.All(stops, stop => Assert.Empty(stop.Event.Payload)); for (int i = 0; i < expectedCount; i++) { @@ -416,10 +416,10 @@ private static void VerifyStartStopEvents(ConcurrentQueue } } - private static async Task WaitForEventAsync(ConcurrentQueue events, string name) + private static async Task WaitForEventAsync(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, string name) { DateTime startTime = DateTime.UtcNow; - while (!events.Any(e => e.EventName == name)) + while (!events.Any(e => e.Event.EventName == name)) { if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30)) throw new TimeoutException($"Timed out waiting for {name}"); @@ -428,12 +428,12 @@ private static async Task WaitForEventAsync(ConcurrentQueue events) + private static async Task WaitForEventCountersAsync(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events) { DateTime startTime = DateTime.UtcNow; int startCount = events.Count; - while (events.Skip(startCount).Count(IsBytesSentEventCounter) < 2) + while (events.Skip(startCount).Count(e => IsBytesSentEventCounter(e.Event)) < 2) { if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30)) throw new TimeoutException($"Timed out waiting for EventCounters"); @@ -452,11 +452,11 @@ static bool IsBytesSentEventCounter(EventWrittenEventArgs e) } } - private static void VerifyEventCounters(ConcurrentQueue events, int connectCount, bool connectOnly = false, bool shouldHaveTransferedBytes = false, bool shouldHaveDatagrams = false) + private static void VerifyEventCounters(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int connectCount, bool connectOnly = false, bool shouldHaveTransferedBytes = false, bool shouldHaveDatagrams = false) { Dictionary eventCounters = events - .Where(e => e.EventName == "EventCounters") - .Select(e => (IDictionary)e.Payload.Single()) + .Where(e => e.Event.EventName == "EventCounters") + .Select(e => (IDictionary)e.Event.Payload.Single()) .GroupBy(d => (string)d["Name"], d => (double)(d.ContainsKey("Mean") ? d["Mean"] : d["Increment"])) .ToDictionary(p => p.Key, p => p.ToArray()); From 35b956440c467c382b442764af798da7d706bb03 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 25 Sep 2020 01:18:42 +0200 Subject: [PATCH 27/27] Remove ConnectCanceled event --- .../System/Net/Sockets/SocketsTelemetry.cs | 26 +++++-------------- .../tests/FunctionalTests/TelemetryTest.cs | 9 +------ 2 files changed, 7 insertions(+), 28 deletions(-) diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index 5957cd647fe19..7b7641f2a4003 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -50,36 +50,27 @@ private void ConnectFailed(SocketError error, string? exceptionMessage) } } - [Event(4, Level = EventLevel.Warning)] - private void ConnectCanceled() - { - if (IsEnabled(EventLevel.Warning, EventKeywords.All)) - { - WriteEvent(eventId: 4); - } - } - - [Event(5, Level = EventLevel.Informational)] + [Event(4, Level = EventLevel.Informational)] private void AcceptStart(string? address) { - WriteEvent(eventId: 5, address); + WriteEvent(eventId: 4, address); } - [Event(6, Level = EventLevel.Informational)] + [Event(5, Level = EventLevel.Informational)] private void AcceptStop() { if (IsEnabled(EventLevel.Informational, EventKeywords.All)) { - WriteEvent(eventId: 6); + WriteEvent(eventId: 5); } } - [Event(7, Level = EventLevel.Error)] + [Event(6, Level = EventLevel.Error)] private void AcceptFailed(SocketError error, string? exceptionMessage) { if (IsEnabled(EventLevel.Error, EventKeywords.All)) { - WriteEvent(eventId: 7, (int)error, exceptionMessage); + WriteEvent(eventId: 6, (int)error, exceptionMessage); } } @@ -102,11 +93,6 @@ public void AfterConnect(SocketError error, string? exceptionMessage = null) } else { - if (error == SocketError.OperationAborted || error == SocketError.NotSocket) - { - ConnectCanceled(); - } - ConnectFailed(error, exceptionMessage); } diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs index 59a7955efe8c1..8f834a5c112c3 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs @@ -122,7 +122,6 @@ await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), asyn VerifyStartStopEvents(events, connect: false, expectedCount: 1); Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); Assert.DoesNotContain(events, e => e.Event.EventName == "AcceptFailed"); VerifyEventCounters(events, connectCount: 1); @@ -158,7 +157,6 @@ await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), asyn VerifyStartStopEvents(events, connect: true, expectedCount: 1); Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); VerifyEventCounters(events, connectCount: 1, connectOnly: true); }, connectMethod, useDnsEndPoint.ToString()).Dispose(); @@ -269,7 +267,7 @@ await Assert.ThrowsAnyAsync(async () => [InlineData("Task", false)] [InlineData("Eap", true)] [InlineData("Eap", false)] - public void EventSource_ConnectAsyncCanceled_LogsConnectCanceled(string connectMethod, bool useDnsEndPoint) + public void EventSource_ConnectAsyncCanceled_LogsConnectFailed(string connectMethod, bool useDnsEndPoint) { RemoteExecutor.Invoke(async (connectMethod, useDnsEndPointString) => { @@ -331,16 +329,12 @@ private static void VerifyConnectFailureEvents(ConcurrentQueue<(EventWrittenEven VerifyStartStopEvents(events, connect: true, expectedCount: 1); - (EventWrittenEventArgs Event, Guid ActivityId) canceled = Assert.Single(events, e => e.Event.EventName == "ConnectCanceled"); - Assert.Empty(canceled.Event.Payload); - (EventWrittenEventArgs Event, Guid ActivityId) failed = Assert.Single(events, e => e.Event.EventName == "ConnectFailed"); Assert.Equal(2, failed.Event.Payload.Count); Assert.True(Enum.IsDefined((SocketError)failed.Event.Payload[0])); Assert.IsType(failed.Event.Payload[1]); (_, Guid startActivityId) = Assert.Single(events, e => e.Event.EventName == "ConnectStart"); - Assert.Equal(startActivityId, canceled.ActivityId); Assert.Equal(startActivityId, failed.ActivityId); VerifyEventCounters(events, connectCount: 0); @@ -386,7 +380,6 @@ await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), asyn VerifyStartStopEvents(events, connect: true, expectedCount: 10); Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectFailed"); - Assert.DoesNotContain(events, e => e.Event.EventName == "ConnectCanceled"); VerifyEventCounters(events, connectCount: 10, shouldHaveTransferedBytes: true, shouldHaveDatagrams: true); }