diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 3cde85343aed8..f11b84b34a72e 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -27,6 +27,8 @@ public abstract class DiagnosticsTest : HttpClientHandlerTestBase private static bool EnableActivityPropagationEnvironmentVariableIsNotSetAndRemoteExecutorSupported => string.IsNullOrEmpty(Environment.GetEnvironmentVariable(EnableActivityPropagationEnvironmentVariableSettingName)) && RemoteExecutor.IsSupported; + private static readonly Uri InvalidUri = new("http://nosuchhost.invalid"); + public DiagnosticsTest(ITestOutputHelper output) : base(output) { } [Fact] @@ -46,43 +48,36 @@ public void EventSource_ExistsWithCorrectId() // could interfere with the tests, as well as the enabling of tracing interfering // with those tests. - /// - /// This test must be in the same test collection as any others testing HttpClient/WinHttpHandler - /// DiagnosticSources, since the global logging mechanism makes them conflict inherently. - /// - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool requestLogged = false; + HttpRequestMessage requestLogged = null; + HttpResponseMessage responseLogged = null; Guid requestGuid = Guid.Empty; - bool responseLogged = false; Guid responseGuid = Guid.Empty; bool exceptionLogged = false; bool activityLogged = false; + TaskCompletionSource responseLoggedTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Request")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - requestGuid = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "LoggingRequestId"); - requestLogged = true; + requestLogged = GetProperty(kvp.Value, "Request"); + requestGuid = GetProperty(kvp.Value, "LoggingRequestId"); } else if (kvp.Key.Equals("System.Net.Http.Response")) { Assert.NotNull(kvp.Value); - - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); - responseGuid = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "LoggingRequestId"); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + responseLogged = GetProperty(kvp.Value, "Response"); + responseGuid = GetProperty(kvp.Value, "LoggingRequestId"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.RanToCompletion, requestStatus); - - responseLogged = true; + responseLoggedTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.Exception")) { @@ -97,32 +92,30 @@ public void SendAsync_ExpectedDiagnosticSourceLogging() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(s => !s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } - Assert.True(requestLogged, "Request was not logged."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => responseLogged, TimeSpan.FromSeconds(1), - "Response was not logged within 1 second timeout."); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + (HttpRequestMessage request, HttpResponseMessage response) = await GetAsync(useVersion, testAsync, uri); + + await responseLoggedTcs.Task; + + Assert.Same(request, requestLogged); + Assert.Same(response, responseLogged); + }, + async server => await server.HandleRequestAsync()); + Assert.Equal(requestGuid, responseGuid); Assert.False(exceptionLogged, "Exception was logged for successful request"); Assert.False(activityLogged, "HttpOutReq was logged while HttpOutReq logging was disabled"); - diagnosticListenerObserver.Disable(); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - /// - /// This test must be in the same test collection as any others testing HttpClient/WinHttpHandler - /// DiagnosticSources, since the global logging mechanism makes them conflict inherently. - /// - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceNoLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { bool requestLogged = false; bool responseLogged = false; @@ -151,26 +144,23 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - using (HttpClient client = CreateHttpClient(useVersionString)) - { - LoopbackServer.CreateServerAsync(async (server, url) => + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => { - Task> requestLines = server.AcceptConnectionSendResponseAndCloseAsync(); - Task response = client.GetAsync(url); - await new Task[] { response, requestLines }.WhenAllOrAnyFailed(); - - AssertNoHeadersAreInjected(requestLines.Result); - response.Result.Dispose(); - }).GetAwaiter().GetResult(); - } + await GetAsync(useVersion, testAsync, uri); + }, + async server => + { + HttpRequestData request = await server.AcceptConnectionSendResponseAndCloseAsync(); + AssertNoHeadersAreInjected(request); + }); Assert.False(requestLogged, "Request was logged while logging disabled."); Assert.False(activityStartLogged, "HttpRequestOut.Start was logged while logging disabled."); - WaitForFalse(() => responseLogged, TimeSpan.FromSeconds(1), - "Response was logged while logging disabled."); + Assert.False(responseLogged, "Response was logged while logging disabled."); Assert.False(activityStopLogged, "HttpRequestOut.Stop was logged while logging disabled."); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } [ActiveIssue("https://github.com/dotnet/runtime/issues/1477", TestPlatforms.AnyUnix)] @@ -180,7 +170,7 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() [InlineData(true)] public void SendAsync_HttpTracingEnabled_Succeeds(bool useSsl) { - RemoteExecutor.Invoke(async (useVersionString, useSslString) => + RemoteExecutor.Invoke(async (useVersion, useSslString) => { using (var listener = new TestEventListener("Private.InternalDiagnostics.System.Net.Http", EventLevel.Verbose)) { @@ -188,7 +178,7 @@ public void SendAsync_HttpTracingEnabled_Succeeds(bool useSsl) await listener.RunWithCallbackAsync(events.Enqueue, async () => { // Exercise various code paths to get coverage of tracing - using (HttpClient client = CreateHttpClient(useVersionString)) + using (HttpClient client = CreateHttpClient(useVersion)) { // Do a get to a loopback server await LoopbackServer.CreateServerAsync(async (server, url) => @@ -222,116 +212,124 @@ public void SendAsync_HttpTracingEnabled_Succeeds(bool useSsl) }, UseVersion.ToString(), useSsl.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticExceptionLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool exceptionLogged = false; - bool responseLogged = false; + Exception exceptionLogged = null; + + TaskCompletionSource responseLoggedTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Response")) { Assert.NotNull(kvp.Value); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); - - responseLogged = true; + responseLoggedTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.Exception")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); - - exceptionLogged = true; + exceptionLogged = GetProperty(kvp.Value, "Exception"); } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable(s => !s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - Assert.ThrowsAsync(() => client.GetAsync($"http://_{Guid.NewGuid().ToString("N")}.com")) - .GetAwaiter().GetResult(); - } + diagnosticListenerObserver.Enable(); + + Exception ex = await Assert.ThrowsAsync(() => GetAsync(useVersion, testAsync, InvalidUri)); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => responseLogged, TimeSpan.FromSeconds(1), - "Response with exception was not logged within 1 second timeout."); - Assert.True(exceptionLogged, "Exception was not logged"); - diagnosticListenerObserver.Disable(); + await responseLoggedTcs.Task; + + Assert.Same(ex, exceptionLogged); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [ActiveIssue("https://github.com/dotnet/runtime/issues/23167")] - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticCancelledLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool cancelLogged = false; + TaskCompletionSource responseLoggedTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Response")) { Assert.NotNull(kvp.Value); - var status = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + TaskStatus status = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Canceled, status); - Volatile.Write(ref cancelLogged, true); + responseLoggedTcs.SetResult(); + } + else if (kvp.Key == "System.Net.Http.HttpRequestOut.Stop") + { + Assert.NotNull(kvp.Value); + GetProperty(kvp.Value, "Request"); + TaskStatus status = GetProperty(kvp.Value, "RequestTaskStatus"); + Assert.Equal(TaskStatus.Canceled, status); + activityStopTcs.SetResult();; } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable(s => !s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - LoopbackServer.CreateServerAsync(async (server, url) => + diagnosticListenerObserver.Enable(); + + var cts = new CancellationTokenSource(); + + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await Assert.ThrowsAsync(() => GetAsync(useVersion, testAsync, uri, cts.Token)); + }, + async server => { - CancellationTokenSource tcs = new CancellationTokenSource(); - Task request = server.AcceptConnectionAsync(connection => + await server.AcceptConnectionAsync(async connection => { - tcs.Cancel(); - return connection.ReadRequestHeaderAndSendResponseAsync(); + cts.Cancel(); + + await responseLoggedTcs.Task; + await activityStopTcs.Task; }); - Task response = client.GetAsync(url, tcs.Token); - await Assert.ThrowsAnyAsync(() => - TestHelper.WhenAllCompletedOrAnyFailed(response, request)); - }).GetAwaiter().GetResult(); - } + }); } - - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => Volatile.Read(ref cancelLogged), TimeSpan.FromSeconds(1), - "Cancellation was not logged within 1 second timeout."); - diagnosticListenerObserver.Disable(); - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedDiagnosticSourceActivityLoggingRequestId() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(ActivityIdFormat.Hierarchical)] + [InlineData(ActivityIdFormat.W3C)] + public void SendAsync_ExpectedDiagnosticSourceActivityLogging(ActivityIdFormat idFormat) { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync, idFormatString) => { + ActivityIdFormat idFormat = Enum.Parse(idFormatString); + bool requestLogged = false; bool responseLogged = false; - bool activityStartLogged = false; - bool activityStopLogged = false; bool exceptionLogged = false; + HttpRequestMessage activityStartRequestLogged = null; + HttpRequestMessage activityStopRequestLogged = null; + HttpResponseMessage activityStopResponseLogged = null; + + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); Activity parentActivity = new Activity("parent"); + parentActivity.SetIdFormat(idFormat); parentActivity.AddBaggage("correlationId", Guid.NewGuid().ToString("N").ToString()); parentActivity.AddBaggage("moreBaggage", Guid.NewGuid().ToString("N").ToString()); - parentActivity.AddTag("tag", "tag"); //add tag to ensure it is not injected into request + parentActivity.AddTag("tag", "tag"); // add tag to ensure it is not injected into request + parentActivity.Start(); + Assert.Equal(idFormat, parentActivity.IdFormat); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Request")) @@ -351,9 +349,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingRequestId() Assert.NotNull(kvp.Value); Assert.NotNull(Activity.Current); Assert.Equal(parentActivity, Activity.Current.Parent); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - - activityStartLogged = true; + activityStartRequestLogged = GetProperty(kvp.Value, "Request"); } else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { @@ -361,136 +357,51 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingRequestId() Assert.NotNull(Activity.Current); Assert.Equal(parentActivity, Activity.Current.Parent); Assert.True(Activity.Current.Duration != TimeSpan.Zero); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + activityStopRequestLogged = GetProperty(kvp.Value, "Request"); + activityStopResponseLogged = GetProperty(kvp.Value, "Response"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.RanToCompletion, requestStatus); - - activityStopLogged = true; + activityStopTcs.SetResult();; } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(s => s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - LoopbackServer.CreateServerAsync(async (server, url) => - { - Task> requestLines = server.AcceptConnectionSendResponseAndCloseAsync(); - Task response = client.GetAsync(url); - await new Task[] { response, requestLines }.WhenAllOrAnyFailed(); - - AssertHeadersAreInjected(requestLines.Result, parentActivity); - response.Result.Dispose(); - }).GetAwaiter().GetResult(); - } - - Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); - Assert.False(requestLogged, "Request was logged when Activity logging was enabled."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); - Assert.False(exceptionLogged, "Exception was logged for successful request"); - Assert.False(responseLogged, "Response was logged when Activity logging was enabled."); - diagnosticListenerObserver.Disable(); - } - }, UseVersion.ToString()).Dispose(); - } - - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedDiagnosticSourceActivityLoggingW3C() - { - RemoteExecutor.Invoke(useVersionString => - { - bool requestLogged = false; - bool responseLogged = false; - bool activityStartLogged = false; - bool activityStopLogged = false; - bool exceptionLogged = false; - - Activity parentActivity = new Activity("parent"); - parentActivity.SetParentId(ActivityTraceId.CreateRandom(), ActivitySpanId.CreateRandom()); - parentActivity.AddBaggage("moreBaggage", Guid.NewGuid().ToString("N").ToString()); - parentActivity.Start(); - - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => - { - if (kvp.Key.Equals("System.Net.Http.Request")) - { - requestLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.Response")) - { - responseLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.Exception")) - { - exceptionLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Start")) - { - Assert.NotNull(kvp.Value); - Assert.NotNull(Activity.Current); - Assert.Equal(parentActivity, Activity.Current.Parent); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - activityStartLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) - { - Assert.NotNull(kvp.Value); - Assert.NotNull(Activity.Current); - Assert.Equal(parentActivity, Activity.Current.Parent); - Assert.True(Activity.Current.Duration != TimeSpan.Zero); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); - Assert.Equal(TaskStatus.RanToCompletion, requestStatus); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + (HttpRequestMessage request, HttpResponseMessage response) = await GetAsync(useVersion, testAsync, uri); - activityStopLogged = true; - } - }); + await activityStopTcs.Task; - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) - { - diagnosticListenerObserver.Enable(s => s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - LoopbackServer.CreateServerAsync(async (server, url) => + Assert.Same(request, activityStartRequestLogged); + Assert.Same(request, activityStopRequestLogged); + Assert.Same(response, activityStopResponseLogged); + }, + async server => { - Task> requestLines = server.AcceptConnectionSendResponseAndCloseAsync(); - Task response = client.GetAsync(url); - await new Task[] { response, requestLines }.WhenAllOrAnyFailed(); - - AssertHeadersAreInjected(requestLines.Result, parentActivity); - response.Result.Dispose(); - }).GetAwaiter().GetResult(); - } + HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); + AssertHeadersAreInjected(requestData, parentActivity); + }); - Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); Assert.False(requestLogged, "Request was logged when Activity logging was enabled."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); Assert.False(exceptionLogged, "Exception was logged for successful request"); Assert.False(responseLogged, "Response was logged when Activity logging was enabled."); - diagnosticListenerObserver.Disable(); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString(), idFormat.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceActivityLogging_InvalidBaggage() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool activityStopLogged = false; bool exceptionLogged = false; + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + Activity parentActivity = new Activity("parent"); parentActivity.SetIdFormat(ActivityIdFormat.Hierarchical); parentActivity.AddBaggage("bad/key", "value"); @@ -506,18 +417,16 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging_InvalidBaggage() Assert.NotNull(Activity.Current); Assert.Equal(parentActivity, Activity.Current.Parent); Assert.True(Activity.Current.Duration != TimeSpan.Zero); - var request = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + HttpRequestMessage request = GetProperty(kvp.Value, "Request"); Assert.True(request.Headers.TryGetValues("Request-Id", out var requestId)); Assert.True(request.Headers.TryGetValues("Correlation-Context", out var correlationContext)); Assert.Equal(3, correlationContext.Count()); Assert.Contains("key=value", correlationContext); Assert.Contains("bad%2Fkey=value", correlationContext); Assert.Contains("goodkey=bad%2Fvalue", correlationContext); - - var requestStatus = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.RanToCompletion, requestStatus); - - activityStopLogged = true; + activityStopTcs.SetResult();; } else if (kvp.Key.Equals("System.Net.Http.Exception")) { @@ -528,27 +437,29 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging_InvalidBaggage() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(s => s.Contains("HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), "Response was not logged within 1 second timeout."); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => await server.HandleRequestAsync()); + + await activityStopTcs.Task; + Assert.False(exceptionLogged, "Exception was logged for successful request"); - diagnosticListenerObserver.Disable(); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteHeader() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { bool activityStartLogged = false; - bool activityStopLogged = false; + + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); Activity parentActivity = new Activity("parent"); parentActivity.SetIdFormat(ActivityIdFormat.Hierarchical); @@ -560,52 +471,49 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteHea { if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Start")) { - var request = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + HttpRequestMessage request = GetProperty(kvp.Value, "Request"); request.Headers.Add("Request-Id", customRequestIdHeader); activityStartLogged = true; } else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { - var request = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + HttpRequestMessage request = GetProperty(kvp.Value, "Request"); Assert.Single(request.Headers.GetValues("Request-Id")); Assert.Equal(customRequestIdHeader, request.Headers.GetValues("Request-Id").Single()); Assert.False(request.Headers.TryGetValues("traceparent", out var _)); Assert.False(request.Headers.TryGetValues("tracestate", out var _)); - activityStopLogged = true; + activityStopTcs.SetResult();; } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } - Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => await server.HandleRequestAsync()); + + await activityStopTcs.Task; - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); - diagnosticListenerObserver.Disable(); + Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteW3CTraceParentHeader() { - Assert.True(UseVersion.Major < 2, "The test currently only supports HTTP/1."); - RemoteExecutor.Invoke((useVersionString, testAsyncString) => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { bool activityStartLogged = false; - bool activityStopLogged = false; + + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); Activity parentActivity = new Activity("parent"); parentActivity.SetParentId(ActivityTraceId.CreateRandom(), ActivitySpanId.CreateRandom()); @@ -617,8 +525,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteW3C { if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Start")) { - var request = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + HttpRequestMessage request = GetProperty(kvp.Value, "Request"); Assert.Single(request.Headers.GetValues("traceparent")); Assert.False(request.Headers.TryGetValues("tracestate", out var _)); Assert.Equal(customTraceParentHeader, request.Headers.GetValues("traceparent").Single()); @@ -629,35 +536,38 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteW3C } else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { - activityStopLogged = true; + activityStopTcs.SetResult();; } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); - using (var request = new HttpRequestMessage(HttpMethod.Get, Configuration.Http.RemoteEchoServer)) - using (HttpClient client = CreateHttpClient(useVersionString)) - { - request.Headers.Add("traceparent", customTraceParentHeader); - client.SendAsync(bool.Parse(testAsyncString), request).Result.Dispose(); - } - Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + using HttpClient client = CreateHttpClient(useVersion); + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = Version.Parse(useVersion) + }; + request.Headers.Add("traceparent", customTraceParentHeader); + await client.SendAsync(bool.Parse(testAsync), request); + }, + async server => await server.HandleRequestAsync()); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); - diagnosticListenerObserver.Disable(); + await activityStopTcs.Task; + + Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); } }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { bool activityStartLogged = false; bool activityStopLogged = false; @@ -676,157 +586,155 @@ public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable((s, r, _) => - { - if (s.StartsWith("System.Net.Http.HttpRequestOut")) + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => { - var request = r as HttpRequestMessage; - if (request != null) - return !request.RequestUri.Equals(Configuration.Http.RemoteEchoServer); - } + diagnosticListenerObserver.Enable((s, r, _) => + { + if (s.StartsWith("System.Net.Http.HttpRequestOut") && r is HttpRequestMessage request) + { + return request.RequestUri != uri; + } + return true; + }); - return true; - }); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } + await GetAsync(useVersion, testAsync, uri); + }, + async server => await server.HandleRequestAsync()); Assert.False(activityStartLogged, "HttpRequestOut.Start was logged while URL disabled."); - // Poll with a timeout since logging response is not synchronized with returning a response. Assert.False(activityStopLogged, "HttpRequestOut.Stop was logged while URL disabled."); - diagnosticListenerObserver.Disable(); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool exceptionLogged = false; - bool activityStopLogged = false; + Exception exceptionLogged = null; + + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + GetProperty(kvp.Value, "Request"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); - - activityStopLogged = true; + activityStopTcs.SetResult();; } else if (kvp.Key.Equals("System.Net.Http.Exception")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); - - exceptionLogged = true; + exceptionLogged = GetProperty(kvp.Value, "Exception"); } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - Assert.ThrowsAsync(() => client.GetAsync($"http://_{Guid.NewGuid().ToString("N")}.com")) - .GetAwaiter().GetResult(); - } - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "Response with exception was not logged within 1 second timeout."); - Assert.True(exceptionLogged, "Exception was not logged"); - diagnosticListenerObserver.Disable(); + Exception ex = await Assert.ThrowsAsync(() => GetAsync(useVersion, testAsync, InvalidUri)); + + await activityStopTcs.Task; + + Assert.Same(ex, exceptionLogged); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSynchronousExceptionActivityLogging() { - RemoteExecutor.Invoke((useVersionString , testAsyncString)=> + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool exceptionLogged = false; - bool activityStopLogged = false; + Exception exceptionLogged = null; + + TaskCompletionSource activityStopTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - var requestStatus = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + GetProperty(kvp.Value, "Request"); + TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); - - activityStopLogged = true; + activityStopTcs.SetResult();; } else if (kvp.Key.Equals("System.Net.Http.Exception")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); - - exceptionLogged = true; + exceptionLogged = GetProperty(kvp.Value, "Exception"); } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); - using (HttpClientHandler handler = CreateHttpClientHandler(useVersionString)) - using (HttpClient client = CreateHttpClient(handler, useVersionString)) + + using (HttpClientHandler handler = CreateHttpClientHandler(useVersion)) + using (HttpClient client = CreateHttpClient(handler, useVersion)) { // Set a https proxy. - handler.Proxy = new WebProxy($"https://_{Guid.NewGuid().ToString("N")}.com", false); - HttpRequestMessage request = - new HttpRequestMessage(HttpMethod.Get, $"http://_{Guid.NewGuid().ToString("N")}.com"); - // Forces a synchronous exception for SocketsHttpHandler. // SocketsHttpHandler only allow http scheme for proxies. + handler.Proxy = new WebProxy($"https://foo.bar", false); + var request = new HttpRequestMessage(HttpMethod.Get, InvalidUri) + { + Version = Version.Parse(useVersion) + }; // We cannot use Assert.Throws(() => { SendAsync(...); }) to verify the // synchronous exception here, because DiagnosticsHandler SendAsync() method has async // modifier, and returns Task. If the call is not awaited, the current test method will continue // run before the call is completed, thus Assert.Throws() will not capture the exception. // We need to wait for the Task to complete synchronously, to validate the exception. - bool testAsync = bool.Parse(testAsyncString); - Task sendTask = client.SendAsync(testAsync, request); - if (!testAsync) + + Exception exception = null; + if (bool.Parse(testAsync)) { - // In sync test case we execute client.Send(...) in separate thread to prevent deadlocks, - // so it will never finish immediately and we need to wait for it. - ((IAsyncResult)sendTask).AsyncWaitHandle.WaitOne(); + Task sendTask = client.SendAsync(request); + Assert.True(sendTask.IsFaulted); + exception = sendTask.Exception.InnerException; } - Assert.True(sendTask.IsFaulted); - Assert.IsType(sendTask.Exception.InnerException); - } + else + { + try + { + client.Send(request); + } + catch (Exception ex) + { + exception = ex; + } + Assert.NotNull(exception); + } + + await activityStopTcs.Task; - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "Response with exception was not logged within 1 second timeout."); - Assert.True(exceptionLogged, "Exception was not logged"); - diagnosticListenerObserver.Disable(); + Assert.IsType(exception); + Assert.Same(exceptionLogged, exception); + } } }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticSourceNewAndDeprecatedEventsLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { bool requestLogged = false; - bool responseLogged = false; bool activityStartLogged = false; bool activityStopLogged = false; + TaskCompletionSource responseLoggedTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Request")) @@ -835,7 +743,7 @@ public void SendAsync_ExpectedDiagnosticSourceNewAndDeprecatedEventsLogging() } else if (kvp.Key.Equals("System.Net.Http.Response")) { - responseLogged = true; + responseLoggedTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Start")) { @@ -850,30 +758,33 @@ public void SendAsync_ExpectedDiagnosticSourceNewAndDeprecatedEventsLogging() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } + + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => await server.HandleRequestAsync()); + + await responseLoggedTcs.Task; Assert.True(activityStartLogged, "HttpRequestOut.Start was not logged."); Assert.True(requestLogged, "Request was not logged."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); - Assert.True(responseLogged, "Response was not logged."); - diagnosticListenerObserver.Disable(); + Assert.True(activityStopLogged, "HttpRequestOut.Stop was not logged."); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedDiagnosticExceptionOnlyActivityLogging() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - bool exceptionLogged = false; bool activityLogged = false; + Exception exceptionLogged = null; + + TaskCompletionSource exceptionLoggedTcs = new(TaskCreationOptions.RunContinuationsAsynchronously); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) @@ -883,225 +794,129 @@ public void SendAsync_ExpectedDiagnosticExceptionOnlyActivityLogging() else if (kvp.Key.Equals("System.Net.Http.Exception")) { Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); - - exceptionLogged = true; + exceptionLogged = GetProperty(kvp.Value, "Exception"); + exceptionLoggedTcs.SetResult(); } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(s => s.Equals("System.Net.Http.Exception")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - Assert.ThrowsAsync(() => client.GetAsync($"http://_{Guid.NewGuid().ToString("N")}.com")) - .GetAwaiter().GetResult(); - } - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => exceptionLogged, TimeSpan.FromSeconds(1), - "Exception was not logged within 1 second timeout."); - Assert.False(activityLogged, "HttpOutReq was logged when logging was disabled"); - diagnosticListenerObserver.Disable(); - } - }, UseVersion.ToString()).Dispose(); - } + Exception ex = await Assert.ThrowsAsync(() => GetAsync(useVersion, testAsync, InvalidUri)); - [OuterLoop("Uses external servers")] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedDiagnosticStopOnlyActivityLogging() - { - RemoteExecutor.Invoke(useVersionString => - { - bool activityStartLogged = false; - bool activityStopLogged = false; + await exceptionLoggedTcs.Task; - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => - { - if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Start")) - { - activityStartLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) - { - Assert.NotNull(Activity.Current); - activityStopLogged = true; - } - }); - - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) - { - diagnosticListenerObserver.Enable(s => s.Equals("System.Net.Http.HttpRequestOut")); - using (HttpClient client = CreateHttpClient(useVersionString)) - { - client.GetAsync(Configuration.Http.RemoteEchoServer).Result.Dispose(); - } - - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), - "HttpRequestOut.Stop was not logged within 1 second timeout."); - Assert.False(activityStartLogged, - "HttpRequestOut.Start was logged when start logging was disabled"); - diagnosticListenerObserver.Disable(); + Assert.Same(ex, exceptionLogged); + Assert.False(activityLogged, "HttpOutReq was logged when logging was disabled"); } - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedActivityPropagationWithoutListener() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - using (HttpClient client = CreateHttpClient(useVersionString)) - { - Activity parent = new Activity("parent").Start(); - using HttpResponseMessage response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; + Activity parent = new Activity("parent").Start(); - Assert.True(response.RequestMessage.Headers.Contains(parent.IdFormat == ActivityIdFormat.Hierarchical ? "Request-Id" : "traceparent")); - parent.Stop(); - } - }, UseVersion.ToString()).Dispose(); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => + { + HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); + AssertHeadersAreInjected(requestData, parent); + }); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void SendAsync_ExpectedActivityPropagationWithoutListenerOrParentActivity() { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync) => { - using (HttpClient client = CreateHttpClient(useVersionString)) - { - using HttpResponseMessage response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; - - Assert.False(response.RequestMessage.Headers.Contains("Request-Id")); - Assert.False(response.RequestMessage.Headers.Contains("traceparent")); - Assert.False(response.RequestMessage.Headers.Contains("tracestate")); - Assert.False(response.RequestMessage.Headers.Contains("Correlation-Context")); - } - }, UseVersion.ToString()).Dispose(); + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => + { + HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); + AssertNoHeadersAreInjected(requestData); + }); + }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalTheory(nameof(EnableActivityPropagationEnvironmentVariableIsNotSetAndRemoteExecutorSupported))] - [InlineData("true", true)] - [InlineData("1", true)] - [InlineData("0", false)] - [InlineData("false", false)] - [InlineData("FALSE", false)] - [InlineData("fAlSe", false)] - [InlineData("helloworld", true)] - [InlineData("", true)] - public void SendAsync_SuppressedGlobalStaticPropagationEnvVar(string envVarValue, bool isInstrumentationEnabled) + [InlineData("true")] + [InlineData("1")] + [InlineData("0")] + [InlineData("false")] + [InlineData("FALSE")] + [InlineData("fAlSe")] + [InlineData("helloworld")] + [InlineData("")] + public void SendAsync_SuppressedGlobalStaticPropagationEnvVar(string envVarValue) { - RemoteExecutor.Invoke((innerEnvVarValue, innerIsInstrumentationEnabled) => + RemoteExecutor.Invoke(async (useVersion, testAsync, envVarValue) => { - Environment.SetEnvironmentVariable(EnableActivityPropagationEnvironmentVariableSettingName, innerEnvVarValue); + Environment.SetEnvironmentVariable(EnableActivityPropagationEnvironmentVariableSettingName, envVarValue); + + bool isInstrumentationEnabled = !(envVarValue == "0" || envVarValue.Equals("false", StringComparison.OrdinalIgnoreCase)); - string eventKey = null; bool anyEventLogged = false; var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { anyEventLogged = true; - eventKey = kvp.Key; }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable(s => s.Equals("System.Net.Http.HttpRequestOut")); - using (HttpClient client = new HttpClient()) - { - Activity parent = new Activity("parent").Start(); - using HttpResponseMessage response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; - parent.Stop(); - Assert.Equal(bool.Parse(innerIsInstrumentationEnabled), response.RequestMessage.Headers.Contains( - parent.IdFormat == ActivityIdFormat.Hierarchical ? "Request-Id" : "traceparent")); - } + diagnosticListenerObserver.Enable(); - if (!bool.Parse(innerIsInstrumentationEnabled)) - { - Assert.False(anyEventLogged, $"{eventKey} event logged when Activity is suppressed globally"); - } - else - { - Assert.True(anyEventLogged, $"{eventKey} event was not logged logged when Activity is not suppressed"); - } + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + Activity parent = new Activity("parent").Start(); + (HttpRequestMessage request, _) = await GetAsync(useVersion, testAsync, uri); + + string headerName = parent.IdFormat == ActivityIdFormat.Hierarchical ? "Request-Id" : "traceparent"; + Assert.Equal(isInstrumentationEnabled, request.Headers.Contains(headerName)); + }, + async server => await server.HandleRequestAsync()); - diagnosticListenerObserver.Disable(); + Assert.Equal(isInstrumentationEnabled, anyEventLogged); } - }, envVarValue, isInstrumentationEnabled.ToString()).Dispose(); + }, UseVersion.ToString(), TestAsync.ToString(), envVarValue).Dispose(); } - [OuterLoop("Uses external servers")] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [InlineData(true)] [InlineData(false)] public void SendAsync_SuppressedGlobalStaticPropagationNoListenerAppCtx(bool switchValue) { - RemoteExecutor.Invoke(innerSwitchValue => - { - AppContext.SetSwitch(EnableActivityPropagationAppCtxSettingName, bool.Parse(innerSwitchValue)); - - using (HttpClient client = new HttpClient()) - { - Activity parent = new Activity("parent").Start(); - using HttpResponseMessage response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; - parent.Stop(); - Assert.Equal(bool.Parse(innerSwitchValue), response.RequestMessage.Headers.Contains( - parent.IdFormat == ActivityIdFormat.Hierarchical ? "Request-Id" : "traceparent")); - } - }, switchValue.ToString()).Dispose(); - } - - [ActiveIssue("https://github.com/dotnet/runtime/issues/23167")] - [OuterLoop("Uses external servers")] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedDiagnosticCancelledActivityLogging() - { - RemoteExecutor.Invoke(useVersionString => + RemoteExecutor.Invoke(async (useVersion, testAsync, switchValue) => { - bool cancelLogged = false; - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => - { - if (kvp.Key == "System.Net.Http.HttpRequestOut.Stop") - { - Assert.NotNull(kvp.Value); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - var status = - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); - Assert.Equal(TaskStatus.Canceled, status); - Volatile.Write(ref cancelLogged, true); - } - }); + AppContext.SetSwitch(EnableActivityPropagationAppCtxSettingName, bool.Parse(switchValue)); - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) - { - diagnosticListenerObserver.Enable(); - using (HttpClient client = CreateHttpClient(useVersionString)) + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => { - LoopbackServer.CreateServerAsync(async (server, url) => - { - CancellationTokenSource tcs = new CancellationTokenSource(); - Task request = server.AcceptConnectionAsync(connection => - { - tcs.Cancel(); - return connection.ReadRequestHeaderAndSendResponseAsync(); - }); - Task response = client.GetAsync(url, tcs.Token); - await Assert.ThrowsAnyAsync(() => - TestHelper.WhenAllCompletedOrAnyFailed(response, request)); - }).GetAwaiter().GetResult(); - } - } + Activity parent = new Activity("parent").Start(); + (HttpRequestMessage request, _) = await GetAsync(useVersion, testAsync, uri); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => Volatile.Read(ref cancelLogged), TimeSpan.FromSeconds(1), - "Cancellation was not logged within 1 second timeout."); - diagnosticListenerObserver.Disable(); - }, UseVersion.ToString()).Dispose(); + string headerName = parent.IdFormat == ActivityIdFormat.Hierarchical ? "Request-Id" : "traceparent"; + Assert.Equal(bool.Parse(switchValue), request.Headers.Contains(headerName)); + }, + async server => await server.HandleRequestAsync()); + }, UseVersion.ToString(), TestAsync.ToString(), switchValue.ToString()).Dispose(); } - private static T GetPropertyValueFromAnonymousTypeInstance(object obj, string propertyName) + private static T GetProperty(object obj, string propertyName) { Type t = obj.GetType(); @@ -1114,38 +929,24 @@ private static T GetPropertyValueFromAnonymousTypeInstance(object obj, string return (T)propertyValue; } - private static void WaitForTrue(Func p, TimeSpan timeout, string message) + private static string GetHeaderValue(HttpRequestData request, string name) { - // Assert that spin doesn't time out. - Assert.True(SpinWait.SpinUntil(p, timeout), message); + return request.Headers.SingleOrDefault(h => h.Name.Equals(name, StringComparison.OrdinalIgnoreCase)).Value; } - private static void WaitForFalse(Func p, TimeSpan timeout, string message) + private static void AssertNoHeadersAreInjected(HttpRequestData request) { - // Assert that spin times out. - Assert.False(SpinWait.SpinUntil(p, timeout), message); + Assert.Null(GetHeaderValue(request, "Request-Id")); + Assert.Null(GetHeaderValue(request, "traceparent")); + Assert.Null(GetHeaderValue(request, "tracestate")); + Assert.Null(GetHeaderValue(request, "Correlation-Context")); } - private static string GetHeaderValue(string name, List requestLines) + private static void AssertHeadersAreInjected(HttpRequestData request, Activity parent) { - string header = null; - - foreach (var line in requestLines) - { - if (line.StartsWith(name)) - { - header = line.Substring(name.Length).Trim(' ', ':'); - } - } - - return header; - } - - private static void AssertHeadersAreInjected(List requestLines, Activity parent) - { - string requestId = GetHeaderValue("Request-Id", requestLines); - string traceparent = GetHeaderValue("traceparent", requestLines); - string tracestate = GetHeaderValue("tracestate", requestLines); + string requestId = GetHeaderValue(request, "Request-Id"); + string traceparent = GetHeaderValue(request, "traceparent"); + string tracestate = GetHeaderValue(request, "tracestate"); if (parent.IdFormat == ActivityIdFormat.Hierarchical) { @@ -1163,19 +964,10 @@ private static void AssertHeadersAreInjected(List requestLines, Activity Assert.Equal(parent.TraceStateString, tracestate); } - var correlationContext = new List(); - - foreach (var line in requestLines) - { - if (line.StartsWith("Correlation-Context")) - { - var corrCtxString = line.Substring("Correlation-Context".Length).Trim(' ', ':'); - foreach (var kvp in corrCtxString.Split(',')) - { - correlationContext.Add(NameValueHeaderValue.Parse(kvp)); - } - } - } + List correlationContext = (GetHeaderValue(request, "Correlation-Context") ?? string.Empty) + .Split(',', StringSplitOptions.RemoveEmptyEntries) + .Select(kvp => NameValueHeaderValue.Parse(kvp)) + .ToList(); List> baggage = parent.Baggage.ToList(); Assert.Equal(baggage.Count, correlationContext.Count); @@ -1185,22 +977,14 @@ private static void AssertHeadersAreInjected(List requestLines, Activity } } - private static void AssertNoHeadersAreInjected(List requestLines) + private static async Task<(HttpRequestMessage, HttpResponseMessage)> GetAsync(string useVersion, string testAsync, Uri uri, CancellationToken cancellationToken = default) { - foreach (var line in requestLines) + using HttpClient client = CreateHttpClient(useVersion); + var request = new HttpRequestMessage(HttpMethod.Get, uri) { - Assert.False(line.StartsWith("Request-Id"), - "Request-Id header was injected when instrumentation was disabled"); - - Assert.False(line.StartsWith("traceparent"), - "traceparent header was injected when instrumentation was disabled"); - - Assert.False(line.StartsWith("tracestate"), - "tracestate header was injected when instrumentation was disabled"); - - Assert.False(line.StartsWith("Correlation-Context"), - "Correlation-Context header was injected when instrumentation was disabled"); - } + Version = Version.Parse(useVersion) + }; + return (request, await client.SendAsync(bool.Parse(testAsync), request, cancellationToken)); } } } diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs index fdab702fcb097..a2e3bac550d36 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs @@ -71,11 +71,6 @@ public void Enable(Func writeObserverEnabled) _writeObserverEnabled = writeObserverEnabled; } - public void Disable() - { - _writeObserverEnabled = (name, arg1, arg2) => false; - } - private bool IsEnabled(string s, object arg1, object arg2) { return _writeObserverEnabled.Invoke(s, arg1, arg2); diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTestBase.SocketsHttpHandler.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTestBase.SocketsHttpHandler.cs index a702777612032..aa3bae2d1fea2 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTestBase.SocketsHttpHandler.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTestBase.SocketsHttpHandler.cs @@ -78,6 +78,9 @@ protected static object GetUnderlyingSocketsHttpHandler(HttpClientHandler handle protected LoopbackServerFactory LoopbackServerFactory => GetFactoryForVersion(UseVersion, UseQuicImplementationProvider); + protected static LoopbackServerFactory GetFactoryForVersion(string useVersion, QuicImplementationProvider quicImplementationProvider = null) => + GetFactoryForVersion(Version.Parse(useVersion), quicImplementationProvider); + protected static LoopbackServerFactory GetFactoryForVersion(Version useVersion, QuicImplementationProvider quicImplementationProvider = null) { return useVersion.Major switch diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs index f68f3bd720919..797f97f313023 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs @@ -141,9 +141,15 @@ public sealed class SocketsHttpHandler_HttpProtocolTests_Dribble : HttpProtocolT public SocketsHttpHandler_HttpProtocolTests_Dribble(ITestOutputHelper output) : base(output) { } } - public sealed class SocketsHttpHandler_DiagnosticsTest : DiagnosticsTest + public sealed class SocketsHttpHandler_DiagnosticsTest_Http11 : DiagnosticsTest { - public SocketsHttpHandler_DiagnosticsTest(ITestOutputHelper output) : base(output) { } + public SocketsHttpHandler_DiagnosticsTest_Http11(ITestOutputHelper output) : base(output) { } + } + + public sealed class SocketsHttpHandler_DiagnosticsTest_Http2 : DiagnosticsTest + { + public SocketsHttpHandler_DiagnosticsTest_Http2(ITestOutputHelper output) : base(output) { } + protected override Version UseVersion => HttpVersion.Version20; } public sealed class SocketsHttpHandler_HttpClient_SelectedSites_Test : HttpClient_SelectedSites_Test