diff --git a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj index 55a0df882ceeb0..9dd965698c5dff 100644 --- a/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj +++ b/src/libraries/System.Net.NameResolution/src/System.Net.NameResolution.csproj @@ -13,6 +13,7 @@ + @@ -20,6 +21,8 @@ Link="Common\System\Net\InternalException.cs" /> + 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 54c6864e7e5a8f..98cb7ccbc0b559 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs @@ -1,11 +1,13 @@ // 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.Globalization; using System.Net.Internals; using System.Net.Sockets; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Internal; namespace System.Net { @@ -17,7 +19,22 @@ public static string GetHostName() { NameResolutionPal.EnsureSocketsAreInitialized(); - string name = NameResolutionPal.GetHostName(); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(string.Empty); + + string name; + try + { + name = NameResolutionPal.GetHostName(); + } + catch when (LogFailure(stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(null, name); return name; } @@ -293,22 +310,36 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr { ValidateHostName(hostName); - SocketError errorCode = NameResolutionPal.TryGetAddrInfo(hostName, justAddresses, out string? newHostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(hostName); - if (errorCode != SocketError.Success) + object result; + try { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(hostName, $"{hostName} DNS lookup failed with {errorCode}"); - throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); - } + SocketError errorCode = NameResolutionPal.TryGetAddrInfo(hostName, justAddresses, out string? newHostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); - object result = justAddresses ? (object) - addresses : - new IPHostEntry + if (errorCode != SocketError.Success) { - AddressList = addresses, - HostName = newHostName!, - Aliases = aliases - }; + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(hostName, $"{hostName} DNS lookup failed with {errorCode}"); + throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + } + + result = justAddresses ? (object) + addresses : + new IPHostEntry + { + AddressList = addresses, + HostName = newHostName!, + Aliases = aliases + }; + } + catch when (LogFailure(stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); return result; } @@ -327,21 +358,62 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd // will only return that address and not the full list. // Do a reverse lookup to get the host name. - string? name = NameResolutionPal.TryGetNameInfo(address, out SocketError errorCode, out int nativeErrorCode); - if (errorCode != SocketError.Success) + ValueStopwatch stopwatch = NameResolutionTelemetry.Log.BeforeResolution(address); + + SocketError errorCode; + string? name; + try + { + name = NameResolutionPal.TryGetNameInfo(address, out errorCode, out int nativeErrorCode); + if (errorCode != SocketError.Success) + { + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(address, $"{address} DNS lookup failed with {errorCode}"); + throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + } + Debug.Assert(name != null); + } + catch when (LogFailure(stopwatch)) + { + Debug.Fail("LogFailure should return false"); + throw; + } + + if (NameResolutionTelemetry.Log.IsEnabled()) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(address, $"{address} DNS lookup failed with {errorCode}"); - throw SocketExceptionFactory.CreateSocketException(errorCode, nativeErrorCode); + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + + // Do the forward lookup to get the IPs for that host name + stopwatch = NameResolutionTelemetry.Log.BeforeResolution(name); } - // Do the forward lookup to get the IPs for that host name - errorCode = NameResolutionPal.TryGetAddrInfo(name!, justAddresses, out string? hostName, out string[] aliases, out IPAddress[] addresses, out nativeErrorCode); + object result; + try + { + errorCode = NameResolutionPal.TryGetAddrInfo(name, justAddresses, out string? hostName, out string[] aliases, out IPAddress[] addresses, out int nativeErrorCode); + + if (errorCode != SocketError.Success) + { + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(address, $"forward lookup for '{name}' failed with {errorCode}"); + } - if (errorCode != SocketError.Success) + result = justAddresses ? + (object)addresses : + new IPHostEntry + { + HostName = hostName!, + Aliases = aliases, + AddressList = addresses + }; + } + catch when (LogFailure(stopwatch)) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(address, $"forward lookup for '{name}' failed with {errorCode}"); + Debug.Fail("LogFailure should return false"); + throw; } + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: true); + // One of three things happened: // 1. Success. // 2. There was a ptr record in dns, but not a corollary A/AAA record. @@ -349,15 +421,7 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd // - Workaround, Check "Use this connection's dns suffix in dns registration" on that network // adapter's advanced dns settings. // Return whatever we got. - - return justAddresses ? - (object)addresses : - new IPHostEntry - { - HostName = hostName!, - Aliases = aliases, - AddressList = addresses - }; + return result; } private static Task GetHostEntryCoreAsync(string hostName, bool justReturnParsedIp, bool throwOnIIPAny) => @@ -399,7 +463,42 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR if (NameResolutionPal.SupportsGetAddrInfoAsync && ipAddress is null) { ValidateHostName(hostName); - return NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); + + 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; + } + else + { + return NameResolutionPal.GetAddrInfoAsync(hostName, justAddresses); + } } return justAddresses ? (Task) @@ -429,5 +528,14 @@ private static void ValidateHostName(string hostName) SR.Format(SR.net_toolong, nameof(hostName), MaxHostName.ToString(NumberFormatInfo.CurrentInfo))); } } + + + private static bool LogFailure(ValueStopwatch stopwatch) + { + if (NameResolutionTelemetry.Log.IsEnabled()) + NameResolutionTelemetry.Log.AfterResolution(stopwatch, successful: false); + + return false; + } } } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs new file mode 100644 index 00000000000000..c216dcbf96db52 --- /dev/null +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -0,0 +1,156 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Runtime.InteropServices; +using System.Threading; +using Microsoft.Extensions.Internal; + +namespace System.Net +{ + [EventSource(Name = "System.Net.NameResolution")] + internal sealed class NameResolutionTelemetry : EventSource + { + public static readonly NameResolutionTelemetry Log = new NameResolutionTelemetry(); + + private const int ResolutionStartEventId = 1; + private const int ResolutionStopEventId = 2; + private const int ResolutionFailedEventId = 3; + + private PollingCounter? _lookupsRequestedCounter; + private EventCounter? _lookupsDuration; + + private long _lookupsRequested; + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // The cumulative number of name resolution requests started since events were enabled + _lookupsRequestedCounter ??= new PollingCounter("dns-lookups-requested", this, () => Interlocked.Read(ref _lookupsRequested)) + { + DisplayName = "DNS Lookups Requested" + }; + + _lookupsDuration ??= new EventCounter("dns-lookups-duration", this) + { + DisplayName = "Average DNS Lookup Duration", + DisplayUnits = "ms" + }; + } + } + + + private const int MaxIPFormattedLength = 128; + + [Event(ResolutionStartEventId, Level = EventLevel.Informational)] + private void ResolutionStart(string hostNameOrAddress) => WriteEvent(ResolutionStartEventId, hostNameOrAddress); + + [Event(ResolutionStopEventId, Level = EventLevel.Informational)] + private void ResolutionStop() => WriteEvent(ResolutionStopEventId); + + [Event(ResolutionFailedEventId, Level = EventLevel.Informational)] + private void ResolutionFailed() => WriteEvent(ResolutionFailedEventId); + + + [NonEvent] + public ValueStopwatch BeforeResolution(string hostNameOrAddress) + { + Debug.Assert(hostNameOrAddress != null); + + if (IsEnabled()) + { + Interlocked.Increment(ref _lookupsRequested); + + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) + { + ResolutionStart(hostNameOrAddress); + } + + return ValueStopwatch.StartNew(); + } + + return default; + } + + [NonEvent] + public ValueStopwatch BeforeResolution(IPAddress address) + { + Debug.Assert(address != null); + + if (IsEnabled()) + { + Interlocked.Increment(ref _lookupsRequested); + + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) + { + WriteEvent(ResolutionStartEventId, FormatIPAddressNullTerminated(address, stackalloc char[MaxIPFormattedLength])); + } + + return ValueStopwatch.StartNew(); + } + + return default; + } + + [NonEvent] + public void AfterResolution(ValueStopwatch stopwatch, bool successful) + { + if (stopwatch.IsActive) + { + _lookupsDuration!.WriteMetric(stopwatch.GetElapsedTime().TotalMilliseconds); + + if (IsEnabled(EventLevel.Informational, EventKeywords.None)) + { + if (!successful) + { + ResolutionFailed(); + } + + ResolutionStop(); + } + } + } + + + [NonEvent] + private static Span FormatIPAddressNullTerminated(IPAddress address, Span destination) + { + Debug.Assert(address != null); + + bool success = address.TryFormat(destination, out int charsWritten); + Debug.Assert(success); + + Debug.Assert(charsWritten < destination.Length); + destination[charsWritten] = '\0'; + + return destination.Slice(0, charsWritten + 1); + } + + + // WriteEvent overloads taking Span are imitating string arguments + // Span arguments are expected to be null-terminated + + [NonEvent] + private unsafe void WriteEvent(int eventId, Span arg1) + { + Debug.Assert(!arg1.IsEmpty && arg1.IndexOf('\0') == arg1.Length - 1, "Expecting a null-terminated ROS"); + + if (IsEnabled()) + { + fixed (char* arg1Ptr = &MemoryMarshal.GetReference(arg1)) + { + EventData descr = new EventData + { + DataPointer = (IntPtr)(arg1Ptr), + Size = arg1.Length * sizeof(char) + }; + + WriteEventCore(eventId, eventDataCount: 1, &descr); + } + } + } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj index fc02ae500a67bc..c9984c4fc86b9e 100644 --- a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj @@ -1,6 +1,7 @@ $(NetCoreAppCurrent)-Windows_NT;$(NetCoreAppCurrent)-Unix;$(NetCoreAppCurrent)-Browser + true true @@ -12,6 +13,7 @@ + - \ No newline at end of file + diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs new file mode 100644 index 00000000000000..739ae3c39e064f --- /dev/null +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/TelemetryTest.cs @@ -0,0 +1,145 @@ +// 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 System.Linq; +using System.Net.Sockets; +using Microsoft.DotNet.RemoteExecutor; +using Xunit; + +namespace System.Net.NameResolution.Tests +{ + public class TelemetryTest + { + [Fact] + public static void EventSource_ExistsWithCorrectId() + { + Type esType = typeof(Dns).Assembly.GetType("System.Net.NameResolutionTelemetry", throwOnError: true, ignoreCase: false); + Assert.NotNull(esType); + + Assert.Equal("System.Net.NameResolution", EventSource.GetName(esType)); + Assert.Equal(Guid.Parse("4b326142-bfb5-5ed3-8585-7714181d14b0"), EventSource.GetGuid(esType)); + + Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location)); + } + + [OuterLoop] + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public static void EventSource_ResolveValidHostName_LogsStartStop() + { + RemoteExecutor.Invoke(async () => + { + const string ValidHostName = "microsoft.com"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + await Dns.GetHostEntryAsync(ValidHostName); + await Dns.GetHostAddressesAsync(ValidHostName); + + Dns.GetHostEntry(ValidHostName); + Dns.GetHostAddresses(ValidHostName); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ValidHostName, null, null)); + Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(ValidHostName, null, null)); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + Assert.True(events.Count >= 2 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(6, starts.Length); + Assert.All(starts, s => Assert.Equal(ValidHostName, Assert.Single(s.Payload).ToString())); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(6, stops.Length); + + Assert.DoesNotContain(events, e => e.EventName == "ResolutionFailed"); + }).Dispose(); + } + + [OuterLoop] + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public static void EventSource_ResolveInvalidHostName_LogsStartFailureStop() + { + RemoteExecutor.Invoke(async () => + { + const string InvalidHostName = "invalid...example.com"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostEntryAsync(InvalidHostName)); + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostAddressesAsync(InvalidHostName)); + + Assert.ThrowsAny(() => Dns.GetHostEntry(InvalidHostName)); + Assert.ThrowsAny(() => Dns.GetHostAddresses(InvalidHostName)); + + Assert.ThrowsAny(() => Dns.EndGetHostEntry(Dns.BeginGetHostEntry(InvalidHostName, null, null))); + Assert.ThrowsAny(() => Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(InvalidHostName, null, null))); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + Assert.True(events.Count >= 3 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(6, starts.Length); + Assert.All(starts, s => Assert.Equal(InvalidHostName, Assert.Single(s.Payload).ToString())); + + EventWrittenEventArgs[] failures = events.Where(e => e.EventName == "ResolutionFailed").ToArray(); + Assert.Equal(6, failures.Length); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(6, stops.Length); + }).Dispose(); + } + + [OuterLoop] + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public static void EventSource_GetHostEntryForIP_LogsStartStop() + { + RemoteExecutor.Invoke(async () => + { + const string ValidIPAddress = "8.8.4.4"; + + using var listener = new TestEventListener("System.Net.NameResolution", EventLevel.Informational); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + IPAddress ipAddress = IPAddress.Parse(ValidIPAddress); + + await Dns.GetHostEntryAsync(ValidIPAddress); + await Dns.GetHostEntryAsync(ipAddress); + + Dns.GetHostEntry(ValidIPAddress); + Dns.GetHostEntry(ipAddress); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ValidIPAddress, null, null)); + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ipAddress, null, null)); + }); + + Assert.DoesNotContain(events, e => e.EventId == 0); // errors from the EventSource itself + + // Each GetHostEntry over an IP will yield 2 resolutions + Assert.True(events.Count >= 2 * 2 * 6); + + EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "ResolutionStart").ToArray(); + Assert.Equal(12, starts.Length); + Assert.Equal(6, starts.Count(s => Assert.Single(s.Payload).ToString() == ValidIPAddress)); + + EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "ResolutionStop").ToArray(); + Assert.Equal(12, stops.Length); + + Assert.DoesNotContain(events, e => e.EventName == "ResolutionFailed"); + }).Dispose(); + } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs new file mode 100644 index 00000000000000..cd409cbc602d34 --- /dev/null +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/Fakes/FakeNameResolutionTelemetry.cs @@ -0,0 +1,21 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.Extensions.Internal; + +namespace System.Net +{ + internal class NameResolutionTelemetry + { + public static NameResolutionTelemetry Log => new NameResolutionTelemetry(); + + public bool IsEnabled() => false; + + public ValueStopwatch BeforeResolution(string hostNameOrAddress) => default; + + public ValueStopwatch BeforeResolution(IPAddress address) => default; + + public void AfterResolution(ValueStopwatch stopwatch, bool successful) { } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj b/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj index 8a7d9b76643574..7e3f969094b870 100644 --- a/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj +++ b/src/libraries/System.Net.NameResolution/tests/UnitTests/System.Net.NameResolution.Unit.Tests.csproj @@ -29,6 +29,7 @@ + @@ -40,5 +41,7 @@ Link="Common\System\Net\InternalException.cs" /> + \ No newline at end of file