diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/HttpClientLatencyTelemetryExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/HttpClientLatencyTelemetryExtensions.cs index fa77360a8c1..2e955605fdc 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/HttpClientLatencyTelemetryExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/HttpClientLatencyTelemetryExtensions.cs @@ -33,6 +33,9 @@ public static IServiceCollection AddHttpClientLatencyTelemetry(this IServiceColl _ = services.AddSingleton(); _ = services.AddSingleton(); _ = services.AddTransient(); + _ = services.AddSingleton(); + _ = services.RegisterMeasureNames(HttpMeasures.Measures); + _ = services.RegisterTagNames(HttpTags.Tags); _ = services.AddHttpClientLogEnricher(); return services.ConfigureAll( diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs index bad9b23a415..753b5b9a9f6 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs @@ -23,36 +23,69 @@ internal sealed class HttpClientLatencyLogEnricher : IHttpClientLogEnricher { private static readonly ObjectPool _builderPool = PoolFactory.SharedStringBuilderPool; private readonly HttpClientLatencyContext _latencyContext; - + private readonly HttpLatencyMediator _httpLatencyMediator; private readonly CheckpointToken _enricherInvoked; - public HttpClientLatencyLogEnricher(HttpClientLatencyContext latencyContext, ILatencyContextTokenIssuer tokenIssuer) + public HttpClientLatencyLogEnricher( + HttpClientLatencyContext latencyContext, + ILatencyContextTokenIssuer tokenIssuer, + HttpLatencyMediator httpLatencyMediator) { _latencyContext = latencyContext; + _httpLatencyMediator = httpLatencyMediator; _enricherInvoked = tokenIssuer.GetCheckpointToken(HttpCheckpoints.EnricherInvoked); } - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response, Exception? exception) + public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request, HttpResponseMessage? response, Exception? exception) { if (response != null) { var lc = _latencyContext.Get(); - lc?.AddCheckpoint(_enricherInvoked); - - StringBuilder stringBuilder = _builderPool.Get(); - - // Add serverName, checkpoints to outgoing http logs. - AppendServerName(response.Headers, stringBuilder); - _ = stringBuilder.Append(','); if (lc != null) { - AppendCheckpoints(lc, stringBuilder); + // Add the checkpoint + lc.AddCheckpoint(_enricherInvoked); + + // Use the mediator to record all metrics + _httpLatencyMediator.RecordEnd(lc, response); } - collector.Add("LatencyInfo", stringBuilder.ToString()); + StringBuilder stringBuilder = _builderPool.Get(); + + try + { + /* Add version, serverName, checkpoints, and measures to outgoing http logs. + * Schemas: 1) ServerName,CheckpointName,CheckpointValue + * 2) v1.0,ServerName,TagName,TagValue,CheckpointName,CheckpointValue,MetricName,MetricValue + */ + + // Add version + _ = stringBuilder.Append("v1.0"); + _ = stringBuilder.Append(','); + + // Add server name + AppendServerName(response.Headers, stringBuilder); + _ = stringBuilder.Append(','); + + // Add tags, checkpoints, and measures + if (lc != null) + { + AppendTags(lc, stringBuilder); + _ = stringBuilder.Append(','); + + AppendCheckpoints(lc, stringBuilder); + _ = stringBuilder.Append(','); - _builderPool.Return(stringBuilder); + AppendMeasures(lc, stringBuilder); + } + + collector.Add("LatencyInfo", stringBuilder.ToString()); + } + finally + { + _builderPool.Return(stringBuilder); + } } } @@ -60,25 +93,70 @@ private static void AppendServerName(HttpHeaders headers, StringBuilder stringBu { if (headers.TryGetValues(TelemetryConstants.ServerApplicationNameHeader, out var values)) { - _ = stringBuilder.Append(values!.First()); + _ = stringBuilder.Append(values.First()); } } private static void AppendCheckpoints(ILatencyContext latencyContext, StringBuilder stringBuilder) { + const int MillisecondsPerSecond = 1000; + var latencyData = latencyContext.LatencyData; - for (int i = 0; i < latencyData.Checkpoints.Length; i++) + var checkpointCount = latencyData.Checkpoints.Length; + + for (int i = 0; i < checkpointCount; i++) { _ = stringBuilder.Append(latencyData.Checkpoints[i].Name); _ = stringBuilder.Append('/'); } _ = stringBuilder.Append(','); - for (int i = 0; i < latencyData.Checkpoints.Length; i++) + + for (int i = 0; i < checkpointCount; i++) + { + var cp = latencyData.Checkpoints[i]; + _ = stringBuilder.Append((long)Math.Round(((double)cp.Elapsed / cp.Frequency) * MillisecondsPerSecond)); + _ = stringBuilder.Append('/'); + } + } + + private static void AppendMeasures(ILatencyContext latencyContext, StringBuilder stringBuilder) + { + var latencyData = latencyContext.LatencyData; + var measureCount = latencyData.Measures.Length; + + for (int i = 0; i < measureCount; i++) + { + _ = stringBuilder.Append(latencyData.Measures[i].Name); + _ = stringBuilder.Append('/'); + } + + _ = stringBuilder.Append(','); + + for (int i = 0; i < measureCount; i++) + { + _ = stringBuilder.Append(latencyData.Measures[i].Value); + _ = stringBuilder.Append('/'); + } + } + + private static void AppendTags(ILatencyContext latencyContext, StringBuilder stringBuilder) + { + var latencyData = latencyContext.LatencyData; + var tagCount = latencyData.Tags.Length; + + for (int i = 0; i < tagCount; i++) + { + _ = stringBuilder.Append(latencyData.Tags[i].Name); + _ = stringBuilder.Append('/'); + } + + _ = stringBuilder.Append(','); + + for (int i = 0; i < tagCount; i++) { - var ms = ((double)latencyData.Checkpoints[i].Elapsed / latencyData.Checkpoints[i].Frequency) * 1000; - _ = stringBuilder.Append(ms); + _ = stringBuilder.Append(latencyData.Tags[i].Value); _ = stringBuilder.Append('/'); } } -} +} \ No newline at end of file diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.cs new file mode 100644 index 00000000000..25543ad9c5a --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.cs @@ -0,0 +1,39 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#if NET +using System.Net.Http; +using Microsoft.Extensions.Diagnostics.Latency; + +namespace Microsoft.Extensions.Http.Latency.Internal; + +/// +/// Mediator for HTTP latency operations that coordinates recording HTTP metrics in a latency context. +/// +internal sealed class HttpLatencyMediator +{ + private readonly MeasureToken _gcPauseTime; + private readonly TagToken _httpVersionTag; + + public HttpLatencyMediator(ILatencyContextTokenIssuer tokenIssuer) + { + _gcPauseTime = tokenIssuer.GetMeasureToken(HttpMeasures.GCPauseTime); + _httpVersionTag = tokenIssuer.GetTagToken(HttpTags.HttpVersion); + } + + public void RecordStart(ILatencyContext latencyContext) + { + latencyContext.RecordMeasure(_gcPauseTime, (long)System.GC.GetTotalPauseDuration().TotalMilliseconds * -1L); + } + + public void RecordEnd(ILatencyContext latencyContext, HttpResponseMessage? response = null) + { + latencyContext.AddMeasure(_gcPauseTime, (long)System.GC.GetTotalPauseDuration().TotalMilliseconds); + + if (response != null) + { + latencyContext.SetTag(_httpVersionTag, response.Version.ToString()); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.netfx.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.netfx.cs new file mode 100644 index 00000000000..c5cb350397e --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyMediator.netfx.cs @@ -0,0 +1,27 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +#if !NET + +using System.Net.Http; +using Microsoft.Extensions.Diagnostics.Latency; + +namespace Microsoft.Extensions.Http.Latency.Internal; + +internal sealed class HttpLatencyMediator +{ + private readonly TagToken _httpVersionTag; + + public HttpLatencyMediator(ILatencyContextTokenIssuer tokenIssuer) + { + _httpVersionTag = tokenIssuer.GetTagToken(HttpTags.HttpVersion); + } + + public void RecordEnd(ILatencyContext latencyContext, HttpResponseMessage? response = null) + { + if (response != null) + { + latencyContext?.SetTag(_httpVersionTag, response.Version.ToString()); + } + } +} +#endif \ No newline at end of file diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs index 3180cb890c6..81a0878b3f5 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs @@ -21,14 +21,20 @@ internal sealed class HttpLatencyTelemetryHandler : DelegatingHandler private readonly ILatencyContextProvider _latencyContextProvider; private readonly CheckpointToken _handlerStart; private readonly string _applicationName; +#if NET + private readonly HttpLatencyMediator _latencyMediator; +#endif public HttpLatencyTelemetryHandler(HttpRequestLatencyListener latencyListener, ILatencyContextTokenIssuer tokenIssuer, ILatencyContextProvider latencyContextProvider, - IOptions options, IOptions appMetadata) + IOptions options, IOptions appMetadata, HttpLatencyMediator latencyTelemetryMediator) { _latencyListener = latencyListener; _latencyContextProvider = latencyContextProvider; _handlerStart = tokenIssuer.GetCheckpointToken(HttpCheckpoints.HandlerRequestStart); _applicationName = appMetadata.Value.ApplicationName; +#if NET + _latencyMediator = latencyTelemetryMediator; +#endif if (options.Value.EnableDetailedLatencyBreakdown) { @@ -42,6 +48,10 @@ protected async override Task SendAsync(HttpRequestMessage context.AddCheckpoint(_handlerStart); _latencyListener.LatencyContext.Set(context); +#if NET + _latencyMediator.RecordStart(context); +#endif + _ = request.Headers.TryAddWithoutValidation(TelemetryConstants.ClientApplicationNameHeader, _applicationName); return await base.SendAsync(request, cancellationToken).ConfigureAwait(false); diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpMeasures.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpMeasures.cs new file mode 100644 index 00000000000..adb086a99cc --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpMeasures.cs @@ -0,0 +1,16 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.Extensions.Http.Latency.Internal; + +internal static class HttpMeasures +{ + public const string GCPauseTime = "gcp"; + public const string ConnectionInitiated = "coni"; + + public static readonly string[] Measures = + [ + GCPauseTime, + ConnectionInitiated + ]; +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencyListener.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencyListener.cs index 4179759df35..ae5eef41179 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencyListener.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencyListener.cs @@ -1,6 +1,8 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; +using System.Collections.Concurrent; using System.Collections.Frozen; using System.Collections.Generic; using System.Diagnostics.Tracing; @@ -13,12 +15,19 @@ internal sealed class HttpRequestLatencyListener : EventListener { private const string SocketProviderName = "System.Net.Sockets"; private const string HttpProviderName = "System.Net.Http"; - private const string NameResolutionProivderName = "System.Net.NameResolution"; + private const string NameResolutionProviderName = "System.Net.NameResolution"; - private readonly FrozenDictionary> _eventToTokenMap; + private readonly ConcurrentDictionary _eventSources = new() + { + [SocketProviderName] = null, + [HttpProviderName] = null, + [NameResolutionProviderName] = null + }; internal HttpClientLatencyContext LatencyContext { get; } + private readonly EventToToken _eventToToken; + private int _enabled; internal bool Enabled => _enabled == 1; @@ -26,42 +35,59 @@ internal sealed class HttpRequestLatencyListener : EventListener public HttpRequestLatencyListener(HttpClientLatencyContext latencyContext, ILatencyContextTokenIssuer tokenIssuer) { LatencyContext = latencyContext; - _eventToTokenMap = EventToCheckpointToken.Build(tokenIssuer); + _eventToToken = new(tokenIssuer); } public void Enable() { if (Interlocked.CompareExchange(ref _enabled, 1, 0) == 0) { + // Enable any already discovered event sources + foreach (var eventSource in _eventSources) + { + if (eventSource.Value != null) + { + EnableEventSource(eventSource.Value); + } + } + #if NETSTANDARD foreach (var eventSource in EventSource.GetSources()) { OnEventSourceCreated(eventSource.Name, eventSource); } #else - // process already existing listeners once again + // Process already existing listeners once again EventSourceCreated += (_, args) => OnEventSourceCreated(args.EventSource!); #endif - } } internal void OnEventWritten(string eventSourceName, string? eventName) { // If event of interest, add a checkpoint for it. - if (eventName != null - && _eventToTokenMap.TryGetValue(eventSourceName, out var tokenMap) - && tokenMap.TryGetValue(eventName, out var token)) + CheckpointToken? token = _eventToToken.GetCheckpointToken(eventSourceName, eventName); + if (token.HasValue) { - LatencyContext.Get()?.AddCheckpoint(token); + var latencyContext = LatencyContext.Get(); + latencyContext?.AddCheckpoint(token.Value); + + // If event of interest, add a presence measure for it. + MeasureToken? mtoken = _eventToToken.GetMeasureToken(eventSourceName, eventName); + + if (mtoken.HasValue) + { + latencyContext?.AddMeasure(mtoken.Value, 1L); + } } } internal void OnEventSourceCreated(string eventSourceName, EventSource eventSource) { - if (Enabled && _eventToTokenMap.ContainsKey(eventSourceName)) + if (_eventSources.ContainsKey(eventSourceName)) { - EnableEvents(eventSource, EventLevel.Informational); + _eventSources[eventSourceName] = eventSource; + EnableEventSource(eventSource); } } @@ -75,7 +101,15 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) OnEventWritten(eventData.EventSource.Name, eventData.EventName); } - private static class EventToCheckpointToken + private void EnableEventSource(EventSource eventSource) + { + if (Enabled) + { + EnableEvents(eventSource, EventLevel.Informational); + } + } + + private sealed class EventToToken { private static readonly Dictionary _socketMap = new() { @@ -103,32 +137,77 @@ private static class EventToCheckpointToken { "ResponseContentStop", HttpCheckpoints.ResponseContentEnd } }; - public static FrozenDictionary> Build(ILatencyContextTokenIssuer tokenIssuer) + private static readonly Dictionary _httpMeasureMap = new() + { + { "ConnectionEstablished", HttpMeasures.ConnectionInitiated } + }; + + private readonly FrozenDictionary> _eventToCheckpointTokenMap; + private readonly FrozenDictionary> _eventToMeasureTokenMap; + + public EventToToken(ILatencyContextTokenIssuer tokenIssuer) { - Dictionary socket = []; - foreach (var kv in _socketMap) + Dictionary socket = new(); + foreach (string key in _socketMap.Keys) + { + socket[key] = tokenIssuer.GetCheckpointToken(_socketMap[key]); + } + + Dictionary nameResolution = new(); + foreach (string key in _nameResolutionMap.Keys) { - socket[kv.Key] = tokenIssuer.GetCheckpointToken(kv.Value); + nameResolution[key] = tokenIssuer.GetCheckpointToken(_nameResolutionMap[key]); } - Dictionary nameResolution = []; - foreach (var kv in _nameResolutionMap) + Dictionary http = new(); + foreach (string key in _httpMap.Keys) { - nameResolution[kv.Key] = tokenIssuer.GetCheckpointToken(kv.Value); + http[key] = tokenIssuer.GetCheckpointToken(_httpMap[key]); } - Dictionary http = []; - foreach (var kv in _httpMap) + Dictionary httpMeasures = new(); + foreach (string key in _httpMeasureMap.Keys) { - http[kv.Key] = tokenIssuer.GetCheckpointToken(kv.Value); + httpMeasures[key] = tokenIssuer.GetMeasureToken(_httpMeasureMap[key]); } - return new Dictionary> + _eventToCheckpointTokenMap = new Dictionary> { - { SocketProviderName, socket.ToFrozenDictionary() }, - { NameResolutionProivderName, nameResolution.ToFrozenDictionary() }, - { HttpProviderName, http.ToFrozenDictionary() } - }.ToFrozenDictionary(); + { SocketProviderName, socket.ToFrozenDictionary(StringComparer.Ordinal) }, + { NameResolutionProviderName, nameResolution.ToFrozenDictionary(StringComparer.Ordinal) }, + { HttpProviderName, http.ToFrozenDictionary(StringComparer.Ordinal) } + }.ToFrozenDictionary(StringComparer.Ordinal); + + _eventToMeasureTokenMap = new Dictionary> + { + { HttpProviderName, httpMeasures.ToFrozenDictionary(StringComparer.Ordinal) } + }.ToFrozenDictionary(StringComparer.Ordinal); + } + + public CheckpointToken? GetCheckpointToken(string eventSourceName, string? eventName) + { + if (eventName != null && _eventToCheckpointTokenMap.TryGetValue(eventSourceName, out var events)) + { + if (events.TryGetValue(eventName, out var token)) + { + return token; + } + } + + return null; + } + + public MeasureToken? GetMeasureToken(string eventSourceName, string? eventName) + { + if (eventName != null && _eventToMeasureTokenMap.TryGetValue(eventSourceName, out var events)) + { + if (events.TryGetValue(eventName, out var token)) + { + return token; + } + } + + return null; } } } diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpTags.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpTags.cs new file mode 100644 index 00000000000..dd15191e22d --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpTags.cs @@ -0,0 +1,14 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.Extensions.Http.Latency.Internal; + +internal static class HttpTags +{ + public const string HttpVersion = "httpver"; + + public static readonly string[] Tags = + [ + HttpVersion + ]; +} diff --git a/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs index 71941df0e7e..79753bfb996 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs @@ -18,14 +18,14 @@ public class HttpClientLatencyLogEnricherTest public void HttpClientLatencyLogEnricher_NoOp_OnRequest() { var lcti = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti.Object); var checkpoints = new ArraySegment(new[] { new Checkpoint("a", default, default), new Checkpoint("b", default, default) }); var ld = new LatencyData(default, checkpoints, default, default, default); var lc = HttpMockProvider.GetLatencyContext(); lc.Setup(lc => lc.LatencyData).Returns(ld); var context = new HttpClientLatencyContext(); context.Set(lc.Object); - - var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); + var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object, mediator); Mock mockEnrichmentPropertyBag = new Mock(); enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, null, null); mockEnrichmentPropertyBag.Verify(m => m.Add(It.IsAny(), It.IsAny()), Times.Never); @@ -35,6 +35,7 @@ public void HttpClientLatencyLogEnricher_NoOp_OnRequest() public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithoutHeader() { var lcti = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti.Object); var checkpoints = new ArraySegment(new[] { new Checkpoint("a", default, default), new Checkpoint("b", default, default) }); var ld = new LatencyData(default, checkpoints, default, default, default); var lc = HttpMockProvider.GetLatencyContext(); @@ -43,8 +44,7 @@ public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithoutHeader() context.Set(lc.Object); using HttpResponseMessage httpResponseMessage = new(); - - var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); + var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object, mediator); Mock mockEnrichmentPropertyBag = new Mock(); enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, httpResponseMessage, null); @@ -55,6 +55,7 @@ public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithoutHeader() public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithHeader() { var lcti = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti.Object); var checkpoints = new ArraySegment(new[] { new Checkpoint("a", default, default), new Checkpoint("b", default, default) }); var ld = new LatencyData(default, checkpoints, default, default, default); var lc = HttpMockProvider.GetLatencyContext(); @@ -66,7 +67,7 @@ public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithHeader() string serverName = "serverNameVal"; httpResponseMessage.Headers.Add(TelemetryConstants.ServerApplicationNameHeader, serverName); - var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); + var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object, mediator); Mock mockEnrichmentPropertyBag = new Mock(); enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, httpResponseMessage, null); diff --git a/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyMediatorTests.cs b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyMediatorTests.cs new file mode 100644 index 00000000000..b82b815e430 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyMediatorTests.cs @@ -0,0 +1,155 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#if NET +using System; +using System.Net.Http; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.AmbientMetadata; +using Microsoft.Extensions.Diagnostics.Latency; +using Microsoft.Extensions.Http.Latency.Internal; +using Microsoft.Extensions.Options; +using Moq; +using Moq.Protected; +using Xunit; + +namespace Microsoft.Extensions.Http.Latency.Test.Internal; + +public class HttpLatencyMediatorTests +{ + [Fact] + public void RecordStart_RecordsGCPauseMeasure() + { + // Arrange + var lcti = HttpMockProvider.GetTokenIssuer(); + var measureToken = new MeasureToken(HttpMeasures.GCPauseTime, 0); + lcti.Setup(i => i.GetMeasureToken(HttpMeasures.GCPauseTime)) + .Returns(measureToken); + + var lc = HttpMockProvider.GetLatencyContext(); + var mediator = new HttpLatencyMediator(lcti.Object); + + // Act + mediator.RecordStart(lc.Object); + + // Assert + // Verify RecordMeasure was called with the correct token + lc.Verify(c => c.RecordMeasure( + measureToken, + It.Is(v => v <= 0)), // Value should be negative (start value) + Times.Once); + } + + [Fact] + public async Task HttpLatencyTelemetryHandler_UsesMediator() + { + // Arrange + var lc = HttpMockProvider.GetLatencyContext(); + var lcp = HttpMockProvider.GetContextProvider(lc); + lcp.Setup(p => p.CreateContext()).Returns(lc.Object); + + var context = new HttpClientLatencyContext(); + + var sop = new Mock>(); + sop.Setup(a => a.Value).Returns(new ApplicationMetadata()); + var hop = new Mock>(); + hop.Setup(a => a.Value).Returns(new HttpClientLatencyTelemetryOptions()); + + var lcti = HttpMockProvider.GetTokenIssuer(); + + // Create a mediator + var mediator = new HttpLatencyMediator(lcti.Object); + + using var listener = HttpMockProvider.GetListener(context, lcti.Object); + using var req = new HttpRequestMessage(); + req.Method = HttpMethod.Post; + req.RequestUri = new Uri($"https://default-uri.com/foo"); + + var resp = new HttpResponseMessage(); + var mockHandler = new Mock(); + mockHandler.Protected().Setup>( + "SendAsync", + ItExpr.IsAny(), + ItExpr.IsAny()) + .ReturnsAsync(resp); + + using var handler = new HttpLatencyTelemetryHandler( + listener, lcti.Object, lcp.Object, hop.Object, sop.Object, mediator); + handler.InnerHandler = mockHandler.Object; + + // Act + using var client = new HttpClient(handler); + await client.SendAsync(req, It.IsAny()); + + // Verify that the latency context was created and properly used + lcp.Verify(p => p.CreateContext(), Times.Once); + resp.Dispose(); + } + + [Fact] + public void RecordEnd_RecordsGCPauseMeasure() + { + // Arrange + var lcti = HttpMockProvider.GetTokenIssuer(); + var measureToken = new MeasureToken(HttpMeasures.GCPauseTime, 0); + lcti.Setup(i => i.GetMeasureToken(HttpMeasures.GCPauseTime)) + .Returns(measureToken); + + var lc = HttpMockProvider.GetLatencyContext(); + var mediator = new HttpLatencyMediator(lcti.Object); + + // Act + mediator.RecordEnd(lc.Object); + + lc.Verify(c => c.AddMeasure(measureToken, It.IsAny()), Times.Once); + } + + [Fact] + public void RecordEnd_WithResponse_SetsHttpVersionTag() + { + // Arrange + var lcti = HttpMockProvider.GetTokenIssuer(); + var httpVersionToken = new TagToken(HttpTags.HttpVersion, 0); + lcti.Setup(i => i.GetTagToken(HttpTags.HttpVersion)) + .Returns(httpVersionToken); + + var lc = HttpMockProvider.GetLatencyContext(); + var mediator = new HttpLatencyMediator(lcti.Object); + + using var response = new HttpResponseMessage(); + response.Version = new Version(2, 0); + + // Act + mediator.RecordEnd(lc.Object, response); + + // Assert + lc.Verify(c => c.SetTag( + httpVersionToken, + "2.0"), + Times.Once); + } + + [Fact] + public void RecordEnd_WithNullResponse_DoesNotSetHttpVersionTag() + { + // Arrange + var lcti = HttpMockProvider.GetTokenIssuer(); + var httpVersionToken = new TagToken("Http.Version", 0); + lcti.Setup(i => i.GetTagToken(HttpTags.HttpVersion)) + .Returns(httpVersionToken); + + var lc = HttpMockProvider.GetLatencyContext(); + var mediator = new HttpLatencyMediator(lcti.Object); + + // Act + mediator.RecordEnd(lc.Object); + + // Assert + lc.Verify(c => c.SetTag( + It.Is(t => t.Name == HttpTags.HttpVersion), + It.IsAny()), + Times.Never); + } +} +#endif \ No newline at end of file diff --git a/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyTelemetryHandlerTest.cs b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyTelemetryHandlerTest.cs index 2f787284b26..e70f8135d72 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyTelemetryHandlerTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Diagnostics.Tests/Latency/Internal/HttpLatencyTelemetryHandlerTest.cs @@ -1,7 +1,6 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -using System; using System.Linq; using System.Net.Http; using System.Threading; @@ -32,8 +31,9 @@ public void HttpLatencyTelemetryHandler_InvokesTokenIssuer() var lcti = HttpMockProvider.GetTokenIssuer(); var lcti2 = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti2.Object); using var listener = HttpMockProvider.GetListener(context, lcti.Object); - using var handler = new HttpLatencyTelemetryHandler(listener, lcti2.Object, lcp.Object, hop.Object, sop.Object); + using var handler = new HttpLatencyTelemetryHandler(listener, lcti2.Object, lcp.Object, hop.Object, sop.Object, mediator); lcti2.Verify(a => a.GetCheckpointToken(It.Is(s => !HttpCheckpoints.Checkpoints.Contains(s))), Times.Never); lcti2.Verify(a => a.GetCheckpointToken(It.Is(s => HttpCheckpoints.Checkpoints.Contains(s)))); @@ -53,6 +53,7 @@ public async Task HttpLatencyTelemetryHandler_SetsLatencyContext() var lcti = HttpMockProvider.GetTokenIssuer(); var lcti2 = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti2.Object); using var listener = HttpMockProvider.GetListener(context, lcti.Object); using var req = new HttpRequestMessage { @@ -71,12 +72,12 @@ public async Task HttpLatencyTelemetryHandler_SetsLatencyContext() Assert.True(req.Headers.Contains(TelemetryConstants.ClientApplicationNameHeader)); }).Returns(Task.FromResult(resp.Object)); - using var handler = new HttpLatencyTelemetryHandler(listener, lcti2.Object, lcp.Object, hop.Object, sop.Object) + using var handler = new HttpLatencyTelemetryHandler(listener, lcti2.Object, lcp.Object, hop.Object, sop.Object, mediator) { InnerHandler = mockHandler.Object }; - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); await client.SendAsync(req, It.IsAny()); Assert.Null(context.Get()); } @@ -93,8 +94,9 @@ public void HttpLatencyTelemetryHandler_IfDetailsDisabled_DoesNotEnableListener( hop.Setup(a => a.Value).Returns(new HttpClientLatencyTelemetryOptions { EnableDetailedLatencyBreakdown = false }); var lcti = HttpMockProvider.GetTokenIssuer(); + var mediator = new HttpLatencyMediator(lcti.Object); using var listener = HttpMockProvider.GetListener(context, lcti.Object); - using var handler = new HttpLatencyTelemetryHandler(listener, lcti.Object, lcp.Object, hop.Object, sop.Object); + using var handler = new HttpLatencyTelemetryHandler(listener, lcti.Object, lcp.Object, hop.Object, sop.Object, mediator); Assert.False(listener.Enabled); } }