Skip to content

Socket's connect operations tracing #38620

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@
<!-- All configurations -->
<Compile Include="System\Net\Sockets\SocketReceiveFromResult.cs" />
<Compile Include="System\Net\Sockets\SocketReceiveMessageFromResult.cs" />
<Compile Include="System\Net\Sockets\SocketsTelemetry.cs" />
<Compile Include="System\Net\Sockets\SocketTaskExtensions.cs" />
<Compile Include="System\Net\Sockets\IOControlCode.cs" />
<Compile Include="System\Net\Sockets\IPPacketInformation.cs" />
Expand Down
13 changes: 13 additions & 0 deletions src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Diagnostics.Tracing;
using System.Globalization;
using System.IO;
using System.Net.Internals;
Expand Down Expand Up @@ -2071,6 +2072,8 @@ 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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Style-wise I've always found it preferable to eliminate these IsEnabled() calls entirely and rely on the checks that occur inside the EventSource, but I think the mono-linker will fully remove this pattern so its purely style and tiny perf at this point. Style is best decided by the folks who have to work on the code rather than me : )


if (CanUseConnectEx(remoteEP))
{
return BeginConnectEx(remoteEP, flowContext, callback, state);
Expand Down Expand Up @@ -2320,6 +2323,8 @@ asyncResult as MultipleAddressConnectAsyncResult ??
Exception? ex = castedAsyncResult.Result as Exception;
if (ex != null || (SocketError)castedAsyncResult.ErrorCode != SocketError.Success)
{
if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectFailedAndStop((SocketError)castedAsyncResult.ErrorCode, ex?.Message);

if (ex == null)
{
SocketError errorCode = (SocketError)castedAsyncResult.ErrorCode;
Expand All @@ -2334,6 +2339,8 @@ asyncResult as MultipleAddressConnectAsyncResult ??
ExceptionDispatchInfo.Throw(ex);
}

if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStop();

if (NetEventSource.Log.IsEnabled()) NetEventSource.Connected(this, LocalEndPoint, RemoteEndPoint);
}

Expand Down Expand Up @@ -4121,11 +4128,15 @@ static void InitializeSocketsCore()

private void DoConnect(EndPoint endPointSnapshot, Internals.SocketAddress socketAddress)
{
if (SocketsTelemetry.Log.IsEnabled()) SocketsTelemetry.Log.ConnectStart(socketAddress);

SocketError errorCode = SocketPal.Connect(_handle, socketAddress.Buffer, socketAddress.Size);

// 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);
Expand All @@ -4134,6 +4145,8 @@ 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().
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@

using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.InteropServices;
using System.Threading;

Expand Down Expand Up @@ -553,6 +554,9 @@ 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!);
}

internal void CancelConnectAsync()
Expand All @@ -566,6 +570,8 @@ 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)
Expand All @@ -581,6 +587,11 @@ internal void FinishOperationSyncFailure(SocketError socketError, int bytesTrans
{
SetResults(socketError, bytesTransferred, flags);

if (SocketsTelemetry.Log.IsEnabled() && _multipleConnect == null && _completedOperation == SocketAsyncOperation.Connect)
{
SocketsTelemetry.Log.ConnectFailedAndStop(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
Expand Down Expand Up @@ -719,12 +730,16 @@ 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);
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,75 @@
// 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.Tracing;

namespace System.Net.Sockets
{
[EventSource(Name = "System.Net.Sockets")]
internal sealed class SocketsTelemetry : EventSource
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We now have two EventSources in this library. Is that really what we want? I'm not clear on why the decision was made to add a new one. I really don't want to be in a position of having to carry both forward indefinitely.
cc: @noahfalk, @brianrob, @davidsh

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generally, you have one EventSource per area of functionality. There's no hard and fast rule, but unless there's a reason to have multiple EventSources I'd recommend just having one. It also makes it easier to consume the events.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@alnikola, this doesn't need to block your PR, but I do want us to resolve this for .NET 5. Can you please make sure there's an issue for it?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Issue already exists, but it's outside .NET 5.0 scope.

Copy link
Member

@stephentoub stephentoub Jul 3, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is related but different. These PRs are actively doubling the number of event sources used. How is a customer supposed to reason about that: they want socket events, but they need to enable two different providers depending on the events they want? There's no good reason for it. If we're doing a new one because we don't like the old one, we should remove the old one. If we're fine with the old one, we shouldn't introduce the new class. Adding new types like this adds overhead, adds confusion, and adds legacy code to be maintained.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(and if we really want to use that same issue, the description and the milestone should be updated)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I created a dedicated issue #38754 for this, but it needs to be triaged to see if it can fit in .NET 5.0 scope.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added some thoughts to #38754 and may have more once I get a chance to look into this more

{
public static readonly SocketsTelemetry Log = new SocketsTelemetry();

[Event(1, Level = EventLevel.Informational)]
public void ConnectStart(string? address)
{
if (IsEnabled(EventLevel.Informational, EventKeywords.All))
{
WriteEvent(eventId: 1, address ?? "");
}
}

[Event(2, Level = EventLevel.Informational)]
public void ConnectStop()
{
if (IsEnabled(EventLevel.Informational, EventKeywords.All))
{
WriteEvent(eventId: 2);
}
}

[Event(3, Level = EventLevel.Error)]
public void ConnectFailed(SocketError error, string? exceptionMessage)
{
if (IsEnabled(EventLevel.Error, EventKeywords.All))
{
WriteEvent(eventId: 3, (int)error, exceptionMessage ?? string.Empty);
}
}

[Event(4, Level = EventLevel.Warning)]
public void ConnectCanceled()
{
if (IsEnabled(EventLevel.Warning, EventKeywords.All))
{
WriteEvent(eventId: 4);
}
}

[NonEvent]
public void ConnectStart(Internals.SocketAddress address)
{
ConnectStart(address.ToString());
}

[NonEvent]
public void ConnectStart(EndPoint address)
{
ConnectStart(address.ToString());
}

[NonEvent]
public void ConnectCanceledAndStop()
{
ConnectCanceled();
ConnectStop();
}

[NonEvent]
public void ConnectFailedAndStop(SocketError error, string? exceptionMessage)
{
ConnectFailed(error, exceptionMessage);
ConnectStop();
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@
<Compile Include="SelectAndPollTests.cs" />
<Compile Include="SocketInformationTest.cs" />
<Compile Include="TcpListenerTest.cs" />
<Compile Include="TelemetryTest.cs" />
<Compile Include="TimeoutTest.cs" />
<Compile Include="TcpClientTest.cs" />
<Compile Include="Shutdown.cs" />
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
// 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.Concurrent;
using System.Diagnostics.Tracing;
using Microsoft.DotNet.RemoteExecutor;
using Xunit;
using Xunit.Abstractions;

namespace System.Net.Sockets.Tests
{
public class TelemetryTest
{
public readonly ITestOutputHelper _output;

public TelemetryTest(ITestOutputHelper output)
{
_output = output;
}

[Fact]
public static void EventSource_ExistsWithCorrectId()
{
Type esType = typeof(Socket).Assembly.GetType("System.Net.Sockets.SocketsTelemetry", throwOnError: true, ignoreCase: false);
Assert.NotNull(esType);

Assert.Equal("System.Net.Sockets", EventSource.GetName(esType));
Assert.Equal(Guid.Parse("d5b2e7d4-b6ec-50ae-7cde-af89427ad21f"), EventSource.GetGuid(esType));

Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location));
}

[OuterLoop]
[ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))]
public void EventSource_EventsRaisedAsExpected()
{
RemoteExecutor.Invoke(() =>
{
using (var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose))
{
var events = new ConcurrentQueue<EventWrittenEventArgs>();
listener.RunWithCallback(events.Enqueue, () =>
{
// Invoke several tests to execute code paths while tracing is enabled

new SendReceiveSync(null).SendRecv_Stream_TCP(IPAddress.Loopback, false).GetAwaiter();
new SendReceiveSync(null).SendRecv_Stream_TCP(IPAddress.Loopback, true).GetAwaiter();

new SendReceiveTask(null).SendRecv_Stream_TCP(IPAddress.Loopback, false).GetAwaiter();
new SendReceiveTask(null).SendRecv_Stream_TCP(IPAddress.Loopback, true).GetAwaiter();

new SendReceiveEap(null).SendRecv_Stream_TCP(IPAddress.Loopback, false).GetAwaiter();
new SendReceiveEap(null).SendRecv_Stream_TCP(IPAddress.Loopback, true).GetAwaiter();

new SendReceiveApm(null).SendRecv_Stream_TCP(IPAddress.Loopback, false).GetAwaiter();
new SendReceiveApm(null).SendRecv_Stream_TCP(IPAddress.Loopback, true).GetAwaiter();

new NetworkStreamTest().CopyToAsync_AllDataCopied(4096, true).GetAwaiter().GetResult();
new NetworkStreamTest().Timeout_ValidData_Roundtrips().GetAwaiter().GetResult();
});
Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself
Assert.InRange(events.Count, 1, int.MaxValue);
}
}).Dispose();
}
}
}