diff options
author | Liudmila Molkova <lmolkova@microsoft.com> | 2017-04-14 09:28:28 +0300 |
---|---|---|
committer | Liudmila Molkova <lmolkova@microsoft.com> | 2017-04-20 03:07:47 +0300 |
commit | 28b6bbff681b956fbe1e0a5e2133e99dc280b17b (patch) | |
tree | 6cb312cfb01882d64977c154af3e9e0fecaa459c /src/System.Diagnostics.DiagnosticSource | |
parent | 0ad947709f6629cf965a17ab94d9a67c3faf85b2 (diff) |
Start Activity and inject headers in HttpHAndlerDiagnosticListener on Net46
Diffstat (limited to 'src/System.Diagnostics.DiagnosticSource')
2 files changed, 436 insertions, 209 deletions
diff --git a/src/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index b334ef76b5..6532e2c5e3 100644 --- a/src/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -8,6 +8,7 @@ using System.Net; using System.Reflection; using System.Reflection.Emit; using System.Runtime.Serialization; +using System.Text; // This HttpHandlerDiagnosticListener class is applicable only for .NET 4.6, and not for .NET core. @@ -557,33 +558,69 @@ namespace System.Diagnostics private void RaiseRequestEvent(HttpWebRequest request) { - // If System.Net.Http.Request is on, raise the event - if (this.IsEnabled(RequestWriteName)) + if (request.Headers.Get(RequestIdHeaderName) != null) { - long timestamp = Stopwatch.GetTimestamp(); - this.Write(RequestWriteName, - new + // this request was instrumented by previous RaiseRequestEvent + return; + } + + if (this.IsEnabled(ActivityName, request)) + { + var activity = new Activity(ActivityName); + + // Only send start event to users who subscribed for it, but start activity anyway + if (this.IsEnabled(RequestStartName)) + { + long timestamp = Stopwatch.GetTimestamp(); + this.StartActivity(activity, + new + { + Request = request, + Timestamp = timestamp + }); + } + else + { + activity.Start(); + } + + request.Headers.Add(RequestIdHeaderName, activity.Id); + //we expect baggage to be empty or contain a few items + using (IEnumerator<KeyValuePair<string, string>> e = activity.Baggage.GetEnumerator()) + { + if (e.MoveNext()) { - Request = request, - Timestamp = timestamp + StringBuilder baggage = new StringBuilder(); + do + { + KeyValuePair<string, string> item = e.Current; + baggage.Append(item.Key).Append('=').Append(item.Value).Append(','); + } + while (e.MoveNext()); + baggage.Remove(baggage.Length - 1, 1); + request.Headers.Add(CorrelationContextHeaderName, baggage.ToString()); } - ); + } + + // There is no gurantee that Activity.Current will flow to the Response, so let's stop it here + activity.Stop(); } } private void RaiseResponseEvent(HttpWebRequest request, HttpWebResponse response) { - if (this.IsEnabled(ResponseWriteName)) + // Response event could be received several times for the same request + if (request.Headers[RequestIdHeaderName] != null) { + // only send Stop if request was instrumented long timestamp = Stopwatch.GetTimestamp(); - this.Write(ResponseWriteName, + this.Write(RequestStopName, new { Request = request, Response = response, Timestamp = timestamp - } - ); + }); } } @@ -647,9 +684,12 @@ namespace System.Diagnostics #region private fields private const string DiagnosticListenerName = "System.Net.Http.Desktop"; - private const string RequestWriteName = "System.Net.Http.Request"; - private const string ResponseWriteName = "System.Net.Http.Response"; + private const string ActivityName = "System.Net.Http.Desktop.HttpRequestOut"; + private const string RequestStartName = "System.Net.Http.Desktop.HttpRequestOut.Start"; + private const string RequestStopName = "System.Net.Http.Desktop.HttpRequestOut.Stop"; private const string InitializationFailed = "System.Net.Http.InitializationFailed"; + private const string RequestIdHeaderName = "Request-Id"; + private const string CorrelationContextHeaderName = "Correlation-Context"; // Fields for controlling initialization of the HttpHandlerDiagnosticListener singleton private bool initialized = false; diff --git a/src/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 43a58c61a0..faf149e4cb 100644 --- a/src/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -1,9 +1,9 @@ -using System.Collections.Generic; -using System.Diagnostics; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; using System.Net; using System.Net.Http; using System.Reflection; -using System.Text; using System.Threading; using System.Threading.Tasks; using Xunit; @@ -19,15 +19,17 @@ namespace System.Diagnostics.Tests public void TestHttpDiagnosticListenerIsRegistered() { bool listenerFound = false; - DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => - { - if (diagnosticListener.Name == "System.Net.Http.Desktop") + using (DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => { - listenerFound = true; - } - })); + if (diagnosticListener.Name == "System.Net.Http.Desktop") + { + listenerFound = true; + } + }))) + { - Assert.True(listenerFound, "The Http Diagnostic Listener didn't get added to the AllListeners list."); + Assert.True(listenerFound, "The Http Diagnostic Listener didn't get added to the AllListeners list."); + } } /// <summary> @@ -37,105 +39,233 @@ namespace System.Diagnostics.Tests [Fact] public void TestReflectInitializationViaSubscription1() { - EventObserverAndRecorder eventRecords = CreateEventRecorder(); - - // Send a random Http request to generate some events - HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; + using (var eventRecords = new EventObserverAndRecorder()) + { + // Send a random Http request to generate some events + new HttpClient().GetAsync("http://www.bing.com").Wait(); - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= 2, "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.True(eventRecords.Records.Count >= 2, + "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + } } /// <summary> /// A simple test to make sure the Http Diagnostic Source is initialized properly after we subscribed to it, using - /// the subscribe overload with the observer argument and the simple predicate argument. + /// the subscribe overload with just the observer argument and the more compolicating enable filter function. /// </summary> [Fact] public void TestReflectInitializationViaSubscription2() { - EventObserverAndRecorder eventRecords = new EventObserverAndRecorder(); - DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => + using (var eventRecords = new EventObserverAndRecorder(eventName => true)) { - if (diagnosticListener.Name == "System.Net.Http.Desktop") - { - diagnosticListener.Subscribe(eventRecords, (eventName) => { return true; }); - } - })); + // Send a random Http request to generate some events + new HttpClient().GetAsync("http://www.bing.com").Wait(); - // Send a random Http request to generate some events - HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; - - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= 2, "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.True(eventRecords.Records.Count >= 2, + "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + } } /// <summary> /// A simple test to make sure the Http Diagnostic Source is initialized properly after we subscribed to it, using - /// the subscribe overload with just the observer argument and the more compolicating enable filter function. + /// the subscribe overload with the observer argument and the simple predicate argument. /// </summary> [Fact] public void TestReflectInitializationViaSubscription3() { - EventObserverAndRecorder eventRecords = new EventObserverAndRecorder(); - DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => + using (var eventRecords = new EventObserverAndRecorder((eventName, arg1, arg2) => true)) { - if (diagnosticListener.Name == "System.Net.Http.Desktop") + // Send a random Http request to generate some events + new HttpClient().GetAsync("http://www.bing.com").Wait(); + + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.True(eventRecords.Records.Count >= 2, + "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + } + } + + /// <summary> + /// Test to make sure we get both request and response events. + /// </summary> + [Fact] + public async Task TestBasicReceiveAndResponseEvents() + { + using (var eventRecords = new EventObserverAndRecorder()) + { + // Send a random Http request to generate some events + await new HttpClient().GetAsync("http://www.bing.com"); + + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.True(eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop")) >= 1); + + // Check to make sure: The first record must be a request, the next record must be a response. + // The rest is unknown number of responses (it depends on # of redirections) + + KeyValuePair<string, object> startEvent; + Assert.True(eventRecords.Records.TryDequeue(out startEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", startEvent.Key); + WebRequest startRequest = ReadPublicProperty<WebRequest>(startEvent.Value, "Request"); + Assert.NotNull(startRequest.Headers["Request-Id"]); + + KeyValuePair<string, object> stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + WebRequest stopRequest = ReadPublicProperty<WebRequest>(stopEvent.Value, "Request"); + Assert.Equal(startRequest, stopRequest); + + foreach (var pair in eventRecords.Records) { - diagnosticListener.Subscribe(eventRecords, (eventName, obj1, obj2) => { return true; }); + WebRequest thisRequest = ReadPublicProperty<WebRequest>(pair.Value, "Request"); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", pair.Key); + Assert.Equal(startRequest, thisRequest); } - })); + } + } - // Send a random Http request to generate some events - HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; + /// <summary> + /// Test exception in request processing: exception should have expected type/status and now be swallowed by reflection hook + /// </summary> + [Fact] + public async Task TestRequestWithException() + { + using (var eventRecords = new EventObserverAndRecorder()) + { + var ex = + await Assert.ThrowsAsync<HttpRequestException>( + () => new HttpClient().GetAsync($"http://{Guid.NewGuid()}.com")); + + // check that request failed because of the wrong domain name and not because of reflection + var webException = (WebException)ex.InnerException; + Assert.NotNull(webException); + Assert.True(webException.Status == WebExceptionStatus.NameResolutionFailure); + + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(0, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + } + } - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= 2, "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + /// <summary> + /// Test request cancellation: reflection hook does not throw + /// </summary> + [Fact] + public async Task TestCanceledRequest() + { + using (var eventRecords = new EventObserverAndRecorder()) + { + CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(1)); + await Assert.ThrowsAsync<TaskCanceledException>( + () => new HttpClient().GetAsync("http://bing.com", cts.Token)); + + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(0, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + } } /// <summary> - /// Test to make sure we get both request and response events. + /// Test Request-Id and Correlation-Context headers injection /// </summary> [Fact] - public void TestBasicReceiveAndResponseEvents() + public async Task TestActivityIsCreated() { - EventObserverAndRecorder eventRecords = CreateEventRecorder(); + var parentActivity = new Activity("parent").AddBaggage("k1", "v1").AddBaggage("k2", "v2").Start(); + using (var eventRecords = new EventObserverAndRecorder()) + { + await new HttpClient().GetAsync("http://www.bing.com"); - // Send a random Http request to generate some events - HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.True(eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop")) >= 1); - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= 2, "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + WebRequest thisRequest = ReadPublicProperty<WebRequest>(eventRecords.Records.First().Value, "Request"); + var requestId = thisRequest.Headers["Request-Id"]; + var correlationContext = thisRequest.Headers["Correlation-Context"]; - // I can't use the HttpWebRequest type here since it doesn't exist in .net core, so just use "object" - WebRequest firstRequest = null; + Assert.NotNull(requestId); + Assert.True(requestId.StartsWith(parentActivity.Id)); - // Check to make sure: The first record must be a request, the last record must be a response. Records in - // the middle can be anything since it depends on # of redirections - for (int i = 0; i < eventRecords.Records.Count; i++) - { - var pair = eventRecords.Records[i]; - object eventFields = pair.Value; - WebRequest thisRequest = ReadPublicProperty<WebRequest>(eventFields, "Request"); + Assert.NotNull(correlationContext); + Assert.True(correlationContext == "k1=v1,k2=v2" || correlationContext == "k2=v2,k1=v1"); + } + parentActivity.Stop(); + } - if (i == 0) + /// <summary> + /// Tests IsEnabled order and parameters + /// </summary> + [Fact] + public async Task TestIsEnabled() + { + int eventNumber = 0; + + bool IsEnabled(string evnt, object arg1, object arg2) + { + if (eventNumber == 0) { - Assert.Equal("System.Net.Http.Request", pair.Key); - firstRequest = thisRequest; + Assert.True(evnt == "System.Net.Http.Desktop.HttpRequestOut"); + Assert.True(arg1 is WebRequest); } - else if (i == eventRecords.Records.Count - 1) + else if (eventNumber == 1) { - Assert.Equal("System.Net.Http.Response", pair.Key); - Assert.Equal(firstRequest, thisRequest); + Assert.True(evnt == "System.Net.Http.Desktop.HttpRequestOut.Start"); } - else + + eventNumber++; + return true; + } + + using (new EventObserverAndRecorder(IsEnabled)) + { + await new HttpClient().GetAsync("http://www.bing.com"); + Assert.Equal(2, eventNumber); + } + } + + /// <summary> + /// Tests that nothing happens if IsEnabled returns false + /// </summary> + [Fact] + public async Task TestIsEnabledAllOff() + { + using (var eventRecords = new EventObserverAndRecorder((evnt, arg1, arg2) => false)) + { + await new HttpClient().GetAsync("http://www.bing.com"); + + Assert.Equal(0, eventRecords.Records.Count); + } + } + + /// <summary> + /// Tests that if IsEnabled for request is false, request is not instrumented + /// </summary> + [Fact] + public async Task TestIsEnabledRequestOff() + { + bool IsEnabled(string evnt, object arg1, object arg2) + { + if (evnt == "System.Net.Http.Desktop.HttpRequestOut") { - Assert.True(pair.Key == "System.Net.Http.Response" || pair.Key == "System.Net.Http.Request", "An unexpected event of name " + pair.Key + "was received"); - Assert.Equal(firstRequest, thisRequest); + return !(arg1 as WebRequest).RequestUri.ToString().Contains("bing"); } + return true; + } + + using (var eventRecords = new EventObserverAndRecorder(IsEnabled)) + { + await new HttpClient().GetAsync("http://www.bing.com"); + Assert.Equal(0, eventRecords.Records.Count); + + await new HttpClient().GetAsync("http://www.microsoft.com"); + Assert.True(eventRecords.Records.Count > 0); } } @@ -145,38 +275,44 @@ namespace System.Diagnostics.Tests [Fact] public void TestDynamicPropertiesOnReceiveAndResponseEvents() { - EventObserverAndRecorder eventRecords = CreateEventRecorder(); - long beginTimestamp = Stopwatch.GetTimestamp(); + using (var eventRecords = new EventObserverAndRecorder()) + { + long beginTimestamp = Stopwatch.GetTimestamp(); - // Send a random Http request to generate some events - HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; + // Send a random Http request to generate some events + HttpResponseMessage message = new HttpClient().GetAsync("http://www.bing.com").Result; - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= 2, "Didn't get two or more events from Http Diagnostic Listener. Something is wrong."); + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.True(eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop")) >= 1); - // Check to make sure: The first record must be a request, the last record must be a response. Records in - // the middle can be anything since it depends on # of redirections - for (int i = 0; i < eventRecords.Records.Count; i++) - { - var pair = eventRecords.Records[i]; - object eventFields = pair.Value; - Assert.True(pair.Key == "System.Net.Http.Response" || pair.Key == "System.Net.Http.Request", "An unexpected event of name " + pair.Key + "was received"); + // Check to make sure: The first record must be a request, the last record must be a response. Records in + // the middle can be anything since it depends on # of redirections + foreach (var pair in eventRecords.Records) + { + object eventFields = pair.Value; + + Assert.True( + pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Start" || + pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Stop", + "An unexpected event of name " + pair.Key + "was received"); - WebRequest request = ReadPublicProperty<WebRequest>(eventFields, "Request"); - long timestamp = ReadPublicProperty<long>(eventFields, "Timestamp"); + WebRequest request = ReadPublicProperty<WebRequest>(eventFields, "Request"); + long timestamp = ReadPublicProperty<long>(eventFields, "Timestamp"); - Assert.Equal(request.GetType().Name, "HttpWebRequest"); + Assert.Equal(request.GetType().Name, "HttpWebRequest"); - // Just compare the timestamp to make sure it's reasonable. In an poorman experiment, we - // found that 10 secs is roughly 30,000,000 ticks - Assert.True(timestamp - beginTimestamp > 0 && timestamp - beginTimestamp < 30 * 1000 * 1000, $"The timestamp sent with the event doesn't look correct. Begin {beginTimestamp} End {timestamp} Diff {timestamp - beginTimestamp} Expected < {30 * 1000 * 1000}"); + // Just compare the timestamp to make sure it's reasonable. In an poorman experiment, we + // found that 10 secs is roughly 30,000,000 ticks + Assert.True(timestamp - beginTimestamp > 0 && timestamp - beginTimestamp < 30 * 1000 * 1000, $"The timestamp sent with the event doesn't look correct. Begin {beginTimestamp} End {timestamp} Diff {timestamp - beginTimestamp} Expected < {30 * 1000 * 1000}"); - if (pair.Key == "System.Net.Http.Response") - { - object response = ReadPublicProperty<WebResponse>(eventFields, "Response"); - Assert.Equal(response.GetType().Name, "HttpWebResponse"); + if (pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Stop") + { + object response = ReadPublicProperty<WebResponse>(eventFields, "Response"); + Assert.Equal(response.GetType().Name, "HttpWebResponse"); + } } } } @@ -187,111 +323,133 @@ namespace System.Diagnostics.Tests [Fact] public void TestMultipleConcurrentRequests() { - EventObserverAndRecorder eventRecords = CreateEventRecorder(); - long beginTimestamp = Stopwatch.GetTimestamp(); - - Dictionary<string, Tuple<WebRequest, WebResponse>> requestData = new Dictionary<string, Tuple<WebRequest, WebResponse>>(); - requestData.Add("http://www.microsoft.com", null); - requestData.Add("http://www.bing.com", null); - requestData.Add("http://www.xbox.com", null); - requestData.Add("http://www.office.com", null); - requestData.Add("http://www.microsoftstore.com", null); - requestData.Add("http://www.msn.com", null); - requestData.Add("http://outlook.live.com", null); - requestData.Add("http://build.microsoft.com", null); - requestData.Add("http://azure.microsoft.com", null); - requestData.Add("http://www.nuget.org", null); - requestData.Add("http://support.microsoft.com", null); - requestData.Add("http://www.visualstudio.com", null); - requestData.Add("http://msdn.microsoft.com", null); - requestData.Add("http://onedrive.live.com", null); - requestData.Add("http://community.dynamics.com", null); - requestData.Add("http://login.live.com", null); - requestData.Add("http://www.skype.com", null); - requestData.Add("http://channel9.msdn.com", null); - - // Issue all requests simultaneously - HttpClient httpClient = new HttpClient(); - List<Task<HttpResponseMessage>> tasks = new List<Task<HttpResponseMessage>>(); - foreach (string url in requestData.Keys) + var parentActivity = new Activity("parent").Start(); + using (var eventRecords = new EventObserverAndRecorder()) { - tasks.Add(httpClient.GetAsync(url)); - } - - Task.WaitAll(tasks.ToArray()); + long beginTimestamp = Stopwatch.GetTimestamp(); - // Examine the result. Make sure we got them all. + Dictionary<string, Tuple<WebRequest, WebResponse>> requestData = + new Dictionary<string, Tuple<WebRequest, WebResponse>> + { + {"http://www.microsoft.com", null}, + {"http://www.bing.com", null}, + {"http://www.xbox.com", null}, + {"http://www.office.com", null}, + {"http://www.microsoftstore.com", null}, + {"http://www.msn.com", null}, + {"http://outlook.live.com", null}, + {"http://build.microsoft.com", null}, + {"http://azure.microsoft.com", null}, + {"http://www.nuget.org", null}, + {"http://support.microsoft.com", null}, + {"http://www.visualstudio.com", null}, + {"http://msdn.microsoft.com", null}, + {"http://onedrive.live.com", null}, + {"http://community.dynamics.com", null}, + {"http://login.live.com", null}, + {"http://www.skype.com", null}, + {"http://channel9.msdn.com", null} + }; + + // Issue all requests simultaneously + HttpClient httpClient = new HttpClient(); + List<Task<HttpResponseMessage>> tasks = new List<Task<HttpResponseMessage>>(); + + CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + foreach (string url in requestData.Keys) + { + tasks.Add(httpClient.GetAsync(url, cts.Token)); + } - // Just make sure some events are written, to confirm we successfully subscribed to it. We should have - // at least two events, one for request send, and one for response receive - Assert.True(eventRecords.Records.Count >= requestData.Count * 2, "Didn't get two or more events on average from each request. Something is wrong."); + Task.WaitAll(tasks.ToArray()); - // Check to make sure: We have a WebRequest and a WebResponse for each URL - for (int i = 0; i < eventRecords.Records.Count; i++) - { - var pair = eventRecords.Records[i]; - object eventFields = pair.Value; + // Examine the result. Make sure we got them all. - Assert.True(pair.Key == "System.Net.Http.Response" || pair.Key == "System.Net.Http.Request", "An unexpected event of name " + pair.Key + "was received"); + // Just make sure some events are written, to confirm we successfully subscribed to it. We should have + // at least two events, one for request send, and one for response receive + Assert.Equal(requestData.Count, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.True(eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop")) >= requestData.Count); - WebRequest request = ReadPublicProperty<WebRequest>(eventFields, "Request"); - long timestamp = ReadPublicProperty<long>(eventFields, "Timestamp"); + // Check to make sure: We have a WebRequest and a WebResponse for each URL + foreach (var pair in eventRecords.Records) + { + object eventFields = pair.Value; - Assert.Equal(request.GetType().Name, "HttpWebRequest"); + Assert.True( + pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Start" || + pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Stop", + "An unexpected event of name " + pair.Key + "was received"); - // Just compare the timestamp to make sure it's reasonable. In an poorman experiment, we - // found that 10 secs is roughly 30,000,000 ticks - Assert.True(timestamp - beginTimestamp > 0 && timestamp - beginTimestamp < 30 * 1000 * 1000, $"The timestamp sent with the event doesn't look correct. Begin {beginTimestamp} End {timestamp} Diff {timestamp - beginTimestamp} Expected < {30 * 1000 * 1000}"); + long timestamp = ReadPublicProperty<long>(eventFields, "Timestamp"); - if (pair.Key == "System.Net.Http.Request") - { - // Make sure this is an URL that we recognize. If not, just skip - Tuple<WebRequest, WebResponse> tuple = null; - if (!requestData.TryGetValue(request.RequestUri.OriginalString, out tuple)) - { - continue; - } + // Just compare the timestamp to make sure it's reasonable. In an poorman experiment, we + // found that 10 secs is roughly 30,000,000 ticks + Assert.True(timestamp - beginTimestamp > 0 && timestamp - beginTimestamp < 30 * 1000 * 1000, $"The timestamp sent with the event doesn't look correct. Begin {beginTimestamp} End {timestamp} Diff {timestamp - beginTimestamp} Expected < {30 * 1000 * 1000}"); - WebRequest previousSeenRequest = tuple?.Item1; - WebResponse previousSeenResponse = tuple?.Item2; + WebRequest request = ReadPublicProperty<WebRequest>(eventFields, "Request"); + Assert.Equal(request.GetType().Name, "HttpWebRequest"); - // We see have seen an HttpWebRequest before for this URL/host, make sure it's the same one, - // Then update the tuple with the request object, if we didn't have one - Assert.True(previousSeenRequest == null || previousSeenRequest == request, "Didn't expect to see a different WebRequest object going to the same url host for: " + request.RequestUri.OriginalString); - requestData[request.RequestUri.OriginalString] = new Tuple<WebRequest, WebResponse>(previousSeenRequest ?? request, previousSeenResponse); - } - else - { - // This must be the response. - WebResponse response = ReadPublicProperty<WebResponse>(eventFields, "Response"); - Assert.Equal(response.GetType().Name, "HttpWebResponse"); - - // By the time we see the response, the request object may already have been redirected with a different - // url. Hence, it's not reliable to just look up requestData by the URL/hostname. Instead, we have to look - // through each one and match by object reference on the request object. - Tuple<WebRequest, WebResponse> tuple = null; - foreach (Tuple<WebRequest, WebResponse> currentTuple in requestData.Values) + if (pair.Key == "System.Net.Http.Desktop.HttpRequestOut.Start") { - if (currentTuple != null && currentTuple.Item1 == request) + // Make sure this is an URL that we recognize. If not, just skip + Tuple<WebRequest, WebResponse> tuple = null; + if (!requestData.TryGetValue(request.RequestUri.OriginalString, out tuple)) { - // Found it! - tuple = currentTuple; - break; + continue; } + + // all requests have Request-Id with proper parent Id + var requestId = request.Headers["Request-Id"]; + Assert.True(requestId.StartsWith(parentActivity.Id)); + // all request activities are siblings: + var childSuffix = requestId.Substring(0, parentActivity.Id.Length); + Assert.True(childSuffix.IndexOf('.') == childSuffix.Length - 1); + + WebRequest previousSeenRequest = tuple?.Item1; + WebResponse previousSeenResponse = tuple?.Item2; + + // We see have seen an HttpWebRequest before for this URL/host, make sure it's the same one, + // Then update the tuple with the request object, if we didn't have one + Assert.True(previousSeenRequest == null || previousSeenRequest == request, + "Didn't expect to see a different WebRequest object going to the same url host for: " + + request.RequestUri.OriginalString); + requestData[request.RequestUri.OriginalString] = + new Tuple<WebRequest, WebResponse>(previousSeenRequest ?? request, previousSeenResponse); } + else + { + // This must be the response. + WebResponse response = ReadPublicProperty<WebResponse>(eventFields, "Response"); + Assert.Equal(response.GetType().Name, "HttpWebResponse"); + + // By the time we see the response, the request object may already have been redirected with a different + // url. Hence, it's not reliable to just look up requestData by the URL/hostname. Instead, we have to look + // through each one and match by object reference on the request object. + Tuple<WebRequest, WebResponse> tuple = null; + foreach (Tuple<WebRequest, WebResponse> currentTuple in requestData.Values) + { + if (currentTuple != null && currentTuple.Item1 == request) + { + // Found it! + tuple = currentTuple; + break; + } + } - // Update the tuple with the response object - Assert.NotNull(tuple); - requestData[request.RequestUri.OriginalString] = new Tuple<WebRequest, WebResponse>(request, response); + // Update the tuple with the response object + Assert.NotNull(tuple); + requestData[request.RequestUri.OriginalString] = + new Tuple<WebRequest, WebResponse>(request, response); + } } - } - // Finally, make sure we have request and response objects for every entry - foreach (KeyValuePair<string, Tuple<WebRequest, WebResponse>> pair in requestData) - { - Assert.NotNull(pair.Value); - Assert.NotNull(pair.Value.Item1); - Assert.NotNull(pair.Value.Item2); + // Finally, make sure we have request and response objects for every entry + foreach (KeyValuePair<string, Tuple<WebRequest, WebResponse>> pair in requestData) + { + Assert.NotNull(pair.Value); + Assert.NotNull(pair.Value.Item1); + Assert.NotNull(pair.Value.Item2); + } } } @@ -302,19 +460,6 @@ namespace System.Diagnostics.Tests return (T)property.GetValue(obj); } - private EventObserverAndRecorder CreateEventRecorder() - { - EventObserverAndRecorder eventRecords = new EventObserverAndRecorder(); - DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => - { - if (diagnosticListener.Name == "System.Net.Http.Desktop") - { - diagnosticListener.Subscribe(eventRecords); - } - })); - return eventRecords; - } - /// <summary> /// CallbackObserver is a adapter class that creates an observer (which you can pass /// to IObservable.Subscribe), and calls the given callback every time the 'next' @@ -335,13 +480,55 @@ namespace System.Diagnostics.Tests /// EventObserverAndRecorder is an observer that watches all Http diagnosticlistener events flowing /// through, and record all of them /// </summary> - private class EventObserverAndRecorder : IObserver<KeyValuePair<string, object>> + private class EventObserverAndRecorder : IObserver<KeyValuePair<string, object>>, IDisposable { - public List<KeyValuePair<string, object>> Records { get; } = new List<KeyValuePair<string, object>>(); + public EventObserverAndRecorder() + { + listSubscription = DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => + { + if (diagnosticListener.Name == "System.Net.Http.Desktop") + { + httpSubscription = diagnosticListener.Subscribe(this); + } + })); + } + + public EventObserverAndRecorder(Predicate<string> isEnabled) + { + listSubscription = DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => + { + if (diagnosticListener.Name == "System.Net.Http.Desktop") + { + httpSubscription = diagnosticListener.Subscribe(this, isEnabled); + } + })); + } + + public EventObserverAndRecorder(Func<string, object, object, bool> isEnabled) + { + listSubscription = DiagnosticListener.AllListeners.Subscribe(new CallbackObserver<DiagnosticListener>(diagnosticListener => + { + if (diagnosticListener.Name == "System.Net.Http.Desktop") + { + httpSubscription = diagnosticListener.Subscribe(this, isEnabled); + } + })); + } + + public void Dispose() + { + listSubscription.Dispose(); + httpSubscription.Dispose(); + } + + public ConcurrentQueue<KeyValuePair<string, object>> Records { get; } = new ConcurrentQueue<KeyValuePair<string, object>>(); public void OnCompleted() { } public void OnError(Exception error) { } - public void OnNext(KeyValuePair<string, object> record) { Records.Add(record); } + public void OnNext(KeyValuePair<string, object> record) { Records.Enqueue(record); } + + private readonly IDisposable listSubscription; + private IDisposable httpSubscription; } } } |