From 0c7187a3eded956492b74f63c0b549bcc654065d Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 18 Mar 2020 12:54:56 -0700 Subject: [PATCH 1/8] Improved HttpHandlerDiagnosticListener's handling of exceptions thrown during connection creation. Fixed a couple spots where RequestIdHeaderName was checked but not TraceParentHeaderName. --- .../HttpHandlerDiagnosticListener.cs | 129 ++++++++++++------ .../HttpHandlerDiagnosticListenerTests.cs | 21 ++- 2 files changed, 103 insertions(+), 47 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 16023f62623c5d..7a5e2bd22a9b68 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -496,7 +496,7 @@ public override int Add(object value) // which allows us to intercept each new HttpWebRequest object added under // this Connection. ArrayList originalArrayList = s_writeListField.GetValue(value) as ArrayList; - HttpWebRequestArrayList newArrayList = new HttpWebRequestArrayList(originalArrayList ?? new ArrayList()); + HttpWebRequestArrayList newArrayList = new HttpWebRequestArrayList(value, originalArrayList ?? new ArrayList()); s_writeListField.SetValue(value, newArrayList); } @@ -514,22 +514,45 @@ public override int Add(object value) /// private sealed class HttpWebRequestArrayList : ArrayListWrapper { - public HttpWebRequestArrayList(ArrayList list) : base(list) + private readonly object _Connection; + + public HttpWebRequestArrayList(object connection, ArrayList list) : base(list) { + _Connection = connection; } public override int Add(object value) { + // Add before firing events so if some user code cancels/aborts the request it will be found in the outstanding list. + int index = base.Add(value); + HttpWebRequest request = value as HttpWebRequest; if (request != null) { s_instance.RaiseRequestEvent(request); } - return base.Add(value); + return index; } public override void RemoveAt(int index) + { + RemoveRequest(index); + + base.RemoveAt(index); + } + + public override void Clear() + { + for (int index = 0; index < Count; index++) + { + RemoveRequest(index); + } + + base.Clear(); + } + + private void RemoveRequest(int index) { HttpWebRequest request = base[index] as HttpWebRequest; if (request != null) @@ -538,35 +561,41 @@ public override void RemoveAt(int index) if (response != null) { s_instance.RaiseResponseEvent(request, response); + return; } - else - { - // In case reponse content length is 0 and request is async, - // we won't have a HttpWebResponse set on request object when this method is called - // http://referencesource.microsoft.com/#System/net/System/Net/HttpWebResponse.cs,525 - // But we there will be CoreResponseData object that is either exception - // or the internal HTTP reponse representation having status, content and headers + // In case reponse content length is 0 and request is async, + // we won't have a HttpWebResponse set on request object when this method is called + // http://referencesource.microsoft.com/#System/net/System/Net/HttpWebResponse.cs,525 - var coreResponse = s_coreResponseAccessor(request); - if (coreResponse != null && s_coreResponseDataType.IsInstanceOfType(coreResponse)) - { - HttpStatusCode status = s_coreStatusCodeAccessor(coreResponse); - WebHeaderCollection headers = s_coreHeadersAccessor(coreResponse); + // But we there will be CoreResponseData object that is either exception + // or the internal HTTP reponse representation having status, content and headers - // Manual creation of HttpWebResponse here is not possible as this method is eventually called from the - // HttpWebResponse ctor. So we will send Stop event with the Status and Headers payload - // to notify listeners about response; - // We use two different names for Stop events since one event with payload type that varies creates - // complications for efficient payload parsing and is not supported by DiagnosicSource helper - // libraries (e.g. Microsoft.Extensions.DiagnosticAdapter) + var coreResponse = s_coreResponseAccessor(request); + if (coreResponse != null && s_coreResponseDataType.IsInstanceOfType(coreResponse)) + { + HttpStatusCode status = s_coreStatusCodeAccessor(coreResponse); + WebHeaderCollection headers = s_coreHeadersAccessor(coreResponse); + + // Manual creation of HttpWebResponse here is not possible as this method is eventually called from the + // HttpWebResponse ctor. So we will send Stop event with the Status and Headers payload + // to notify listeners about response; + // We use two different names for Stop events since one event with payload type that varies creates + // complications for efficient payload parsing and is not supported by DiagnosicSource helper + // libraries (e.g. Microsoft.Extensions.DiagnosticAdapter) + + s_instance.RaiseResponseEvent(request, status, headers); + return; + } - s_instance.RaiseResponseEvent(request, status, headers); - } + // If an Exception is thrown opening a connection (ex: DNS issues, TLS issue) or something is aborted really early on we will reach here. + var error = s_errorField.GetValue(_Connection) as WebExceptionStatus?; + var exception = s_innerExceptionField.GetValue(_Connection) as Exception; + if (error.HasValue) + { + s_instance.RaiseExceptionEvent(request, error.Value, exception); } } - - base.RemoveAt(index); } } @@ -583,7 +612,7 @@ private HttpHandlerDiagnosticListener() : base(DiagnosticListenerName) private void RaiseRequestEvent(HttpWebRequest request) { - if (request.Headers.Get(RequestIdHeaderName) != null) + if (IsRequestInstrumented(request)) { // this request was instrumented by previous RaiseRequestEvent return; @@ -593,15 +622,7 @@ private void RaiseRequestEvent(HttpWebRequest request) { var activity = new Activity(ActivityName); - // Only send start event to users who subscribed for it, but start activity anyway - if (this.IsEnabled(RequestStartName)) - { - this.StartActivity(activity, new { Request = request }); - } - else - { - activity.Start(); - } + activity.Start(); if (activity.IdFormat == ActivityIdFormat.W3C) { @@ -618,14 +639,11 @@ private void RaiseRequestEvent(HttpWebRequest request) } } } - else + else if (request.Headers.Get(RequestIdHeaderName) == null) { // do not inject header if it was injected already // perhaps tracing systems wants to override it - if (request.Headers.Get(RequestIdHeaderName) == null) - { - request.Headers.Add(RequestIdHeaderName, activity.Id); - } + request.Headers.Add(RequestIdHeaderName, activity.Id); } if (request.Headers.Get(CorrelationContextHeaderName) == null) @@ -648,18 +666,28 @@ private void RaiseRequestEvent(HttpWebRequest request) } } + // Only send start event to users who subscribed for it, but start activity anyway + if (this.IsEnabled(RequestStartName)) + { + Write(activity.OperationName + ".Start", new { Request = request }); + } + // There is no guarantee that Activity.Current will flow to the Response, so let's stop it here activity.Stop(); } } + private bool IsRequestInstrumented(HttpWebRequest request) + { + return request.Headers.Get(TraceParentHeaderName) != null || request.Headers.Get(RequestIdHeaderName) != null; + } + private void RaiseResponseEvent(HttpWebRequest request, HttpWebResponse response) { // Response event could be received several times for the same request in case it was redirected // IsLastResponse checks if response is the last one (no more redirects will happen) // based on response StatusCode and number or redirects done so far - bool wasRequestInstrumented = request.Headers.Get(TraceParentHeaderName) != null || request.Headers.Get(RequestIdHeaderName) != null; - if (wasRequestInstrumented && IsLastResponse(request, response.StatusCode)) + if (IsRequestInstrumented(request) && IsLastResponse(request, response.StatusCode)) { // only send Stop if request was instrumented this.Write(RequestStopName, new { Request = request, Response = response }); @@ -671,12 +699,20 @@ private void RaiseResponseEvent(HttpWebRequest request, HttpStatusCode statusCod // Response event could be received several times for the same request in case it was redirected // IsLastResponse checks if response is the last one (no more redirects will happen) // based on response StatusCode and number or redirects done so far - if (request.Headers.Get(RequestIdHeaderName) != null && IsLastResponse(request, statusCode)) + if (IsRequestInstrumented(request) && IsLastResponse(request, statusCode)) { this.Write(RequestStopExName, new { Request = request, StatusCode = statusCode, Headers = headers }); } } + private void RaiseExceptionEvent(HttpWebRequest request, WebExceptionStatus status, Exception exception) + { + if (IsRequestInstrumented(request)) + { + this.Write(RequestExceptionName, new { Request = request, Status = status, Exception = exception }); + } + } + private bool IsLastResponse(HttpWebRequest request, HttpStatusCode statusCode) { if (request.AllowAutoRedirect) @@ -706,6 +742,8 @@ private static void PrepareReflectionObjects() s_connectionListField = s_connectionGroupType?.GetField("m_ConnectionList", BindingFlags.Instance | BindingFlags.NonPublic); s_connectionType = systemNetHttpAssembly?.GetType("System.Net.Connection"); s_writeListField = s_connectionType?.GetField("m_WriteList", BindingFlags.Instance | BindingFlags.NonPublic); + s_errorField = s_connectionType?.GetField("m_Error", BindingFlags.Instance | BindingFlags.NonPublic); + s_innerExceptionField = s_connectionType?.GetField("m_InnerException", BindingFlags.Instance | BindingFlags.NonPublic); s_httpResponseAccessor = CreateFieldGetter("_HttpResponse", BindingFlags.NonPublic | BindingFlags.Instance); s_autoRedirectsAccessor = CreateFieldGetter("_AutoRedirects", BindingFlags.NonPublic | BindingFlags.Instance); @@ -723,6 +761,8 @@ private static void PrepareReflectionObjects() s_connectionListField == null || s_connectionType == null || s_writeListField == null || + s_errorField == null || + s_innerExceptionField == null || s_httpResponseAccessor == null || s_autoRedirectsAccessor == null || s_coreResponseDataType == null || @@ -799,6 +839,7 @@ private static Func CreateFieldGetter(Type classType, st 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 RequestExceptionName = "System.Net.Http.Desktop.HttpRequestOut.Exception"; private const string RequestStopExName = "System.Net.Http.Desktop.HttpRequestOut.Ex.Stop"; private const string InitializationFailed = "System.Net.Http.InitializationFailed"; private const string RequestIdHeaderName = "Request-Id"; @@ -815,6 +856,8 @@ private static Func CreateFieldGetter(Type classType, st private static FieldInfo s_connectionListField; private static Type s_connectionType; private static FieldInfo s_writeListField; + private static FieldInfo s_errorField; + private static FieldInfo s_innerExceptionField; private static Func s_httpResponseAccessor; private static Func s_autoRedirectsAccessor; private static Func s_coreResponseAccessor; diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 89d8e9558ef16d..68fb39a49dc2a4 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -161,6 +161,8 @@ public async Task TestW3CHeaders() (await client.GetAsync(Configuration.Http.RemoteEchoServer)).Dispose(); } + Assert.Equal(2, eventRecords.Records.Count()); + // Check to make sure: The first record must be a request, the next record must be a response. KeyValuePair startEvent; Assert.True(eventRecords.Records.TryDequeue(out startEvent)); @@ -212,6 +214,8 @@ public async Task TestW3CHeadersTraceStateAndCorrelationContext() parent.Stop(); + Assert.Equal(2, eventRecords.Records.Count()); + // Check to make sure: The first record must be a request, the next record must be a response. Assert.True(eventRecords.Records.TryDequeue(out var evnt)); Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", evnt.Key); @@ -250,6 +254,8 @@ public async Task DoNotInjectRequestIdWhenPresent() (await client.SendAsync(request)).Dispose(); } + Assert.Equal(1, eventRecords.Records.Count()); // Only Stop event is sent. + // Check to make sure: The first record must be a request, the next record must be a response. Assert.True(eventRecords.Records.TryDequeue(out var evnt)); HttpWebRequest startRequest = ReadPublicProperty(evnt.Value, "Request"); @@ -276,6 +282,8 @@ public async Task DoNotInjectTraceParentWhenPresent() (await client.SendAsync(request)).Dispose(); } + Assert.Equal(1, eventRecords.Records.Count()); // Only Stop event is sent. + // Check to make sure: The first record must be a request, the next record must be a response. Assert.True(eventRecords.Records.TryDequeue(out var evnt)); HttpWebRequest startRequest = ReadPublicProperty(evnt.Value, "Request"); @@ -348,6 +356,7 @@ public async Task TestRedirectedRequest() } // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); } @@ -371,9 +380,10 @@ await Assert.ThrowsAsync( Assert.NotNull(webException); Assert.True(webException.Status == WebExceptionStatus.NameResolutionFailure); - // We should have one Start event and no stop event + // We should have one Start event, no Stop event, and one Exception event. + Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); - Assert.Equal(0, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Exception"))); } } @@ -393,9 +403,10 @@ public async Task TestCanceledRequest() Assert.True(ex is TaskCanceledException || ex is WebException); } - // We should have one Start event and no stop event + // We should have one Start event, no Stop event, and one Exception event. + Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); - Assert.Equal(0, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Exception"))); } } @@ -414,6 +425,7 @@ public async Task TestActivityIsCreated() (await client.GetAsync(Configuration.Http.RemoteEchoServer)).Dispose(); } + Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); @@ -447,6 +459,7 @@ public async Task TestInvalidBaggage() (await client.GetAsync(Configuration.Http.RemoteEchoServer)).Dispose(); } + Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); From af404151bd6b4862007f5f9a9be8163490086594 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 18 Mar 2020 15:32:20 -0700 Subject: [PATCH 2/8] Fixed a few style issues. One small optimization. --- .../Diagnostics/HttpHandlerDiagnosticListener.cs | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 7a5e2bd22a9b68..8d75535043841b 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -7,7 +7,6 @@ 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. @@ -66,14 +65,14 @@ private void Initialize() { lock (this) { - if (!this.initialized) + if (!this._initialized) { try { // This flag makes sure we only do this once. Even if we failed to initialize in an // earlier time, we should not retry because this initialization is not cheap and // the likelihood it will succeed the second time is very small. - this.initialized = true; + this._initialized = true; PrepareReflectionObjects(); PerformInjection(); @@ -280,7 +279,7 @@ public override object this[object key] /// private class ArrayListWrapper : ArrayList { - private ArrayList _list; + private readonly ArrayList _list; public override int Capacity { @@ -590,10 +589,9 @@ private void RemoveRequest(int index) // If an Exception is thrown opening a connection (ex: DNS issues, TLS issue) or something is aborted really early on we will reach here. var error = s_errorField.GetValue(_Connection) as WebExceptionStatus?; - var exception = s_innerExceptionField.GetValue(_Connection) as Exception; if (error.HasValue) { - s_instance.RaiseExceptionEvent(request, error.Value, exception); + s_instance.RaiseExceptionEvent(request, error.Value, s_innerExceptionField.GetValue(_Connection) as Exception); } } } @@ -832,7 +830,7 @@ private static Func CreateFieldGetter(Type classType, st #endregion - internal static HttpHandlerDiagnosticListener s_instance = new HttpHandlerDiagnosticListener(); + internal static readonly HttpHandlerDiagnosticListener s_instance = new HttpHandlerDiagnosticListener(); #region private fields private const string DiagnosticListenerName = "System.Net.Http.Desktop"; @@ -848,7 +846,7 @@ private static Func CreateFieldGetter(Type classType, st private const string TraceStateHeaderName = "tracestate"; // Fields for controlling initialization of the HttpHandlerDiagnosticListener singleton - private bool initialized = false; + private bool _initialized = false; // Fields for reflection private static FieldInfo s_connectionGroupListField; From f54a7c915fd853ab2b88feed9ca38a7bfe2c493a Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 19 Mar 2020 11:19:17 -0700 Subject: [PATCH 3/8] Code review. --- .../HttpHandlerDiagnosticListener.cs | 12 +- .../HttpHandlerDiagnosticListenerTests.cs | 130 ++++++++++++++---- 2 files changed, 109 insertions(+), 33 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 8d75535043841b..ac7bd551ba5b05 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -513,11 +513,11 @@ public override int Add(object value) /// private sealed class HttpWebRequestArrayList : ArrayListWrapper { - private readonly object _Connection; + private readonly object _connection; public HttpWebRequestArrayList(object connection, ArrayList list) : base(list) { - _Connection = connection; + _connection = connection; } public override int Add(object value) @@ -588,10 +588,10 @@ private void RemoveRequest(int index) } // If an Exception is thrown opening a connection (ex: DNS issues, TLS issue) or something is aborted really early on we will reach here. - var error = s_errorField.GetValue(_Connection) as WebExceptionStatus?; + var error = s_errorField.GetValue(_connection) as WebExceptionStatus?; if (error.HasValue) { - s_instance.RaiseExceptionEvent(request, error.Value, s_innerExceptionField.GetValue(_Connection) as Exception); + s_instance.RaiseExceptionEvent(request, error.Value, s_innerExceptionField.GetValue(_connection) as Exception); } } } @@ -622,6 +622,10 @@ private void RaiseRequestEvent(HttpWebRequest request) activity.Start(); + // We don't call StartActivity here because it will fire into user code before the headers are added. + // In the case where user code cancels or aborts the request, this can lead to a Stop or Exception + // event NOT firing because IsRequestInstrumented will return false without the headers. + if (activity.IdFormat == ActivityIdFormat.W3C) { // do not inject header if it was injected already diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 68fb39a49dc2a4..9abfe61fa52789 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -112,7 +112,13 @@ public void TestReflectInitializationViaSubscription3() [Fact] public async Task TestBasicReceiveAndResponseEvents() { - using (var eventRecords = new EventObserverAndRecorder()) + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyHeaders(startRequest); + })) { // Send a random Http request to generate some events using (var client = new HttpClient()) @@ -121,19 +127,14 @@ public async Task TestBasicReceiveAndResponseEvents() } // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); - Assert.Equal(2, eventRecords.Records.Count); // Check to make sure: The first record must be a request, the next record must be a response. - KeyValuePair startEvent; - Assert.True(eventRecords.Records.TryDequeue(out startEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", startEvent.Key); - HttpWebRequest startRequest = ReadPublicProperty(startEvent.Value, "Request"); - Assert.NotNull(startRequest); - Assert.NotNull(startRequest.Headers["Request-Id"]); - Assert.Null(startRequest.Headers["traceparent"]); - Assert.Null(startRequest.Headers["tracestate"]); + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyHeaders(startRequest); KeyValuePair stopEvent; Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); @@ -151,7 +152,13 @@ public async Task TestW3CHeaders() { try { - using (var eventRecords = new EventObserverAndRecorder()) + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify W3C header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyW3CHeaders(startRequest); + })) { Activity.DefaultIdFormat = ActivityIdFormat.W3C; Activity.ForceDefaultIdFormat = true; @@ -164,11 +171,46 @@ public async Task TestW3CHeaders() Assert.Equal(2, eventRecords.Records.Count()); // Check to make sure: The first record must be a request, the next record must be a response. - KeyValuePair startEvent; - Assert.True(eventRecords.Records.TryDequeue(out startEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", startEvent.Key); - HttpWebRequest startRequest = ReadPublicProperty(startEvent.Value, "Request"); - Assert.NotNull(startRequest); + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyW3CHeaders(startRequest); + + KeyValuePair stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); + Assert.NotNull(stopRequest); + + HttpWebResponse stopResponse = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(stopResponse); + } + } + finally + { + CleanUp(); + } + } + + [OuterLoop] + [Fact] + public async Task TestW3CHeadersWithoutContent() + { + try + { + using (var eventRecords = new EventObserverAndRecorder()) + { + Activity.DefaultIdFormat = ActivityIdFormat.W3C; + Activity.ForceDefaultIdFormat = true; + // Send a random Http request to generate some events + using (var client = new HttpClient()) + { + (await client.GetAsync(Configuration.Http.RemoteEmptyContentServer)).Dispose(); + } + + Assert.Equal(2, eventRecords.Records.Count()); + + // Check to make sure: The first record must be a request, the next record must be a response. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); var traceparent = startRequest.Headers["traceparent"]; Assert.NotNull(traceparent); @@ -178,12 +220,12 @@ public async Task TestW3CHeaders() KeyValuePair stopEvent; Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Ex.Stop", stopEvent.Key); HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); Assert.NotNull(stopRequest); - HttpWebResponse stopResponse = ReadPublicProperty(stopEvent.Value, "Response"); - Assert.NotNull(stopResponse); + HttpStatusCode status = ReadPublicProperty(stopEvent.Value, "StatusCode"); + Assert.Equal(HttpStatusCode.OK, status); } } finally @@ -217,10 +259,7 @@ public async Task TestW3CHeadersTraceStateAndCorrelationContext() Assert.Equal(2, eventRecords.Records.Count()); // Check to make sure: The first record must be a request, the next record must be a response. - Assert.True(eventRecords.Records.TryDequeue(out var evnt)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", evnt.Key); - HttpWebRequest startRequest = ReadPublicProperty(evnt.Value, "Request"); - Assert.NotNull(startRequest); + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); var traceparent = startRequest.Headers["traceparent"]; var tracestate = startRequest.Headers["tracestate"]; @@ -314,16 +353,12 @@ public async Task TestResponseWithoutContentEvents() } // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); - Assert.Equal(2, eventRecords.Records.Count); // Check to make sure: The first record must be a request, the next record must be a response. - KeyValuePair startEvent; - Assert.True(eventRecords.Records.TryDequeue(out startEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", startEvent.Key); - HttpWebRequest startRequest = ReadPublicProperty(startEvent.Value, "Request"); - Assert.NotNull(startRequest); + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); Assert.NotNull(startRequest.Headers["Request-Id"]); KeyValuePair stopEvent; @@ -384,6 +419,18 @@ await Assert.ThrowsAsync( Assert.Equal(2, eventRecords.Records.Count()); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Exception"))); + + // Check to make sure: The first record must be a request, the next record must be an exception. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + Assert.True(eventRecords.Records.TryDequeue(out KeyValuePair exceptionEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Exception", exceptionEvent.Key); + HttpWebRequest exceptionRequest = ReadPublicProperty(exceptionEvent.Value, "Request"); + Assert.Equal(startRequest, exceptionRequest); + WebExceptionStatus? exceptionStatus = ReadPublicProperty(exceptionEvent.Value, "Status"); + Assert.Equal(WebExceptionStatus.NameResolutionFailure, exceptionStatus); + Exception exceptionException = ReadPublicProperty(exceptionEvent.Value, "Exception"); + Assert.Equal(webException, exceptionException); } } @@ -697,6 +744,31 @@ private static T ReadPublicProperty(object obj, string propertyName) return (T)property.GetValue(obj); } + private static HttpWebRequest AssertFirstEventWasStart(EventObserverAndRecorder eventRecords) + { + Assert.True(eventRecords.Records.TryDequeue(out KeyValuePair startEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Start", startEvent.Key); + HttpWebRequest startRequest = ReadPublicProperty(startEvent.Value, "Request"); + Assert.NotNull(startRequest); + return startRequest; + } + + private static void VerifyHeaders(HttpWebRequest startRequest) + { + Assert.NotNull(startRequest.Headers["Request-Id"]); + Assert.Null(startRequest.Headers["traceparent"]); + Assert.Null(startRequest.Headers["tracestate"]); + } + + private static void VerifyW3CHeaders(HttpWebRequest startRequest) + { + var traceparent = startRequest.Headers["traceparent"]; + Assert.NotNull(traceparent); + Assert.Matches("^[0-9a-f][0-9a-f]-[0-9a-f]{32}-[0-9a-f]{16}-[0-9a-f][0-9a-f]$", traceparent); + Assert.Null(startRequest.Headers["tracestate"]); + Assert.Null(startRequest.Headers["Request-Id"]); + } + /// /// CallbackObserver is an adapter class that creates an observer (which you can pass /// to IObservable.Subscribe), and calls the given callback every time the 'next' From b6ac3ac0078a4ab09e5ebdc180ee5e7dd4a355c4 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Tue, 24 Mar 2020 19:08:01 -0700 Subject: [PATCH 4/8] New design hooking into AsyncCallback. --- .../HttpHandlerDiagnosticListener.cs | 353 ++++++++---------- .../HttpHandlerDiagnosticListenerTests.cs | 111 ++++-- 2 files changed, 235 insertions(+), 229 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index ac7bd551ba5b05..31f6d870cbd028 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -9,15 +9,15 @@ using System.Reflection.Emit; using System.Text; -// This HttpHandlerDiagnosticListener class is applicable only for .NET 4.6, and not for .NET core. +// This HttpHandlerDiagnosticListener class is applicable only for .NET 4.5, and not for .NET core. namespace System.Diagnostics { /// - /// A HttpHandlerDiagnosticListener is a DiagnosticListener for .NET 4.6 and above where + /// A HttpHandlerDiagnosticListener is a DiagnosticListener for .NET 4.5 and above where /// HttpClient doesn't have a DiagnosticListener built in. This class is not used for .NET Core /// because HttpClient in .NET Core already emits DiagnosticSource events. This class compensates for - /// that in .NET 4.6 and above. HttpHandlerDiagnosticListener has no public constructor. To use this, + /// that in .NET 4.5 and above. HttpHandlerDiagnosticListener has no public constructor. To use this, /// the application just needs to call and /// , /// then in the method, @@ -65,14 +65,14 @@ private void Initialize() { lock (this) { - if (!this._initialized) + if (!_initialized) { try { // This flag makes sure we only do this once. Even if we failed to initialize in an // earlier time, we should not retry because this initialization is not cheap and // the likelihood it will succeed the second time is very small. - this._initialized = true; + _initialized = true; PrepareReflectionObjects(); PerformInjection(); @@ -80,7 +80,7 @@ private void Initialize() catch (Exception ex) { // If anything went wrong, just no-op. Write an event so at least we can find out. - this.Write(InitializationFailed, new { Exception = ex }); + Write(InitializationFailed, new { Exception = ex }); } } } @@ -216,11 +216,9 @@ public override object this[object key] } set { - WeakReference weakRef = value as WeakReference; - if (weakRef != null && weakRef.IsAlive) + if (value is WeakReference weakRef && weakRef.IsAlive) { - ServicePoint servicePoint = weakRef.Target as ServicePoint; - if (servicePoint != null) + if (weakRef.Target is ServicePoint servicePoint) { // Replace the ConnectionGroup hashtable inside this ServicePoint object, // which allows us to intercept each new ConnectionGroup object added under @@ -495,7 +493,7 @@ public override int Add(object value) // which allows us to intercept each new HttpWebRequest object added under // this Connection. ArrayList originalArrayList = s_writeListField.GetValue(value) as ArrayList; - HttpWebRequestArrayList newArrayList = new HttpWebRequestArrayList(value, originalArrayList ?? new ArrayList()); + HttpWebRequestArrayList newArrayList = new HttpWebRequestArrayList(originalArrayList ?? new ArrayList()); s_writeListField.SetValue(value, newArrayList); } @@ -513,11 +511,8 @@ public override int Add(object value) /// private sealed class HttpWebRequestArrayList : ArrayListWrapper { - private readonly object _connection; - - public HttpWebRequestArrayList(object connection, ArrayList list) : base(list) + public HttpWebRequestArrayList(ArrayList list) : base(list) { - _connection = connection; } public override int Add(object value) @@ -525,76 +520,13 @@ public override int Add(object value) // Add before firing events so if some user code cancels/aborts the request it will be found in the outstanding list. int index = base.Add(value); - HttpWebRequest request = value as HttpWebRequest; - if (request != null) + if (value is HttpWebRequest request) { s_instance.RaiseRequestEvent(request); } return index; } - - public override void RemoveAt(int index) - { - RemoveRequest(index); - - base.RemoveAt(index); - } - - public override void Clear() - { - for (int index = 0; index < Count; index++) - { - RemoveRequest(index); - } - - base.Clear(); - } - - private void RemoveRequest(int index) - { - HttpWebRequest request = base[index] as HttpWebRequest; - if (request != null) - { - HttpWebResponse response = s_httpResponseAccessor(request); - if (response != null) - { - s_instance.RaiseResponseEvent(request, response); - return; - } - - // In case reponse content length is 0 and request is async, - // we won't have a HttpWebResponse set on request object when this method is called - // http://referencesource.microsoft.com/#System/net/System/Net/HttpWebResponse.cs,525 - - // But we there will be CoreResponseData object that is either exception - // or the internal HTTP reponse representation having status, content and headers - - var coreResponse = s_coreResponseAccessor(request); - if (coreResponse != null && s_coreResponseDataType.IsInstanceOfType(coreResponse)) - { - HttpStatusCode status = s_coreStatusCodeAccessor(coreResponse); - WebHeaderCollection headers = s_coreHeadersAccessor(coreResponse); - - // Manual creation of HttpWebResponse here is not possible as this method is eventually called from the - // HttpWebResponse ctor. So we will send Stop event with the Status and Headers payload - // to notify listeners about response; - // We use two different names for Stop events since one event with payload type that varies creates - // complications for efficient payload parsing and is not supported by DiagnosicSource helper - // libraries (e.g. Microsoft.Extensions.DiagnosticAdapter) - - s_instance.RaiseResponseEvent(request, status, headers); - return; - } - - // If an Exception is thrown opening a connection (ex: DNS issues, TLS issue) or something is aborted really early on we will reach here. - var error = s_errorField.GetValue(_connection) as WebExceptionStatus?; - if (error.HasValue) - { - s_instance.RaiseExceptionEvent(request, error.Value, s_innerExceptionField.GetValue(_connection) as Exception); - } - } - } } #endregion @@ -612,70 +544,50 @@ private void RaiseRequestEvent(HttpWebRequest request) { if (IsRequestInstrumented(request)) { - // this request was instrumented by previous RaiseRequestEvent + // This request was instrumented by previous RaiseRequestEvent, such is the case with redirect responses where the same request is sent again. return; } - if (this.IsEnabled(ActivityName, request)) + if (IsEnabled(ActivityName, request)) { - var activity = new Activity(ActivityName); - - activity.Start(); - // We don't call StartActivity here because it will fire into user code before the headers are added. // In the case where user code cancels or aborts the request, this can lead to a Stop or Exception // event NOT firing because IsRequestInstrumented will return false without the headers. - if (activity.IdFormat == ActivityIdFormat.W3C) - { - // do not inject header if it was injected already - // perhaps tracing systems wants to override it - if (request.Headers.Get(TraceParentHeaderName) == null) - { - request.Headers.Add(TraceParentHeaderName, activity.Id); + var activity = new Activity(ActivityName); + activity.Start(); - var traceState = activity.TraceStateString; - if (traceState != null) - { - request.Headers.Add(TraceStateHeaderName, traceState); - } - } - } - else if (request.Headers.Get(RequestIdHeaderName) == null) - { - // do not inject header if it was injected already - // perhaps tracing systems wants to override it - request.Headers.Add(RequestIdHeaderName, activity.Id); - } + object asyncContext = s_readAResultAccessor(request); - if (request.Headers.Get(CorrelationContextHeaderName) == null) - { - // we expect baggage to be empty or contain a few items - using (IEnumerator> e = activity.Baggage.GetEnumerator()) - { - if (e.MoveNext()) - { - StringBuilder baggage = new StringBuilder(); - do - { - KeyValuePair item = e.Current; - baggage.Append(WebUtility.UrlEncode(item.Key)).Append('=').Append(WebUtility.UrlEncode(item.Value)).Append(','); - } - while (e.MoveNext()); - baggage.Remove(baggage.Length - 1, 1); - request.Headers.Add(CorrelationContextHeaderName, baggage.ToString()); - } - } - } + // Step 1: Hook request._ReadAResult.m_AsyncObject to store the state (request + callback + object + activity) we will need later. + s_asyncObjectModifier(asyncContext, new Tuple(request, s_asyncObjectAccessor(asyncContext), s_asyncCallbackAccessor(asyncContext), activity)); + + // Step 2: Hook request._ReadAResult.m_AsyncCallback so we can fire our events when the request is complete. + s_asyncCallbackModifier(asyncContext, s_asyncCallback); + + InstrumentRequest(request, activity); // Only send start event to users who subscribed for it, but start activity anyway - if (this.IsEnabled(RequestStartName)) + if (IsEnabled(RequestStartName)) { Write(activity.OperationName + ".Start", new { Request = request }); } + } + } + + private void RaiseResponseEvent(HttpWebRequest request, HttpWebResponse response) + { + if (IsEnabled(RequestStopName)) + { + Write(RequestStopName, new { Request = request, Response = response }); + } + } - // There is no guarantee that Activity.Current will flow to the Response, so let's stop it here - activity.Stop(); + private void RaiseExceptionEvent(HttpWebRequest request, Exception exception) + { + if (IsEnabled(RequestExceptionName)) + { + Write(RequestExceptionName, new { Request = request, Exception = exception }); } } @@ -684,53 +596,88 @@ private bool IsRequestInstrumented(HttpWebRequest request) return request.Headers.Get(TraceParentHeaderName) != null || request.Headers.Get(RequestIdHeaderName) != null; } - private void RaiseResponseEvent(HttpWebRequest request, HttpWebResponse response) + private static void InstrumentRequest(HttpWebRequest request, Activity activity) { - // Response event could be received several times for the same request in case it was redirected - // IsLastResponse checks if response is the last one (no more redirects will happen) - // based on response StatusCode and number or redirects done so far - if (IsRequestInstrumented(request) && IsLastResponse(request, response.StatusCode)) + if (activity.IdFormat == ActivityIdFormat.W3C) + { + // do not inject header if it was injected already + // perhaps tracing systems wants to override it + if (request.Headers.Get(TraceParentHeaderName) == null) + { + request.Headers.Add(TraceParentHeaderName, activity.Id); + + string traceState = activity.TraceStateString; + if (traceState != null) + { + request.Headers.Add(TraceStateHeaderName, traceState); + } + } + } + else if (request.Headers.Get(RequestIdHeaderName) == null) { - // only send Stop if request was instrumented - this.Write(RequestStopName, new { Request = request, Response = response }); + // do not inject header if it was injected already + // perhaps tracing systems wants to override it + request.Headers.Add(RequestIdHeaderName, activity.Id); } - } - private void RaiseResponseEvent(HttpWebRequest request, HttpStatusCode statusCode, WebHeaderCollection headers) - { - // Response event could be received several times for the same request in case it was redirected - // IsLastResponse checks if response is the last one (no more redirects will happen) - // based on response StatusCode and number or redirects done so far - if (IsRequestInstrumented(request) && IsLastResponse(request, statusCode)) + if (request.Headers.Get(CorrelationContextHeaderName) == null) { - this.Write(RequestStopExName, new { Request = request, StatusCode = statusCode, Headers = headers }); + // we expect baggage to be empty or contain a few items + using (IEnumerator> e = activity.Baggage.GetEnumerator()) + { + if (e.MoveNext()) + { + StringBuilder baggage = new StringBuilder(); + do + { + KeyValuePair item = e.Current; + baggage.Append(WebUtility.UrlEncode(item.Key)).Append('=').Append(WebUtility.UrlEncode(item.Value)).Append(','); + } + while (e.MoveNext()); + baggage.Remove(baggage.Length - 1, 1); + request.Headers.Add(CorrelationContextHeaderName, baggage.ToString()); + } + } } } - private void RaiseExceptionEvent(HttpWebRequest request, WebExceptionStatus status, Exception exception) + private static void AsyncCallback(IAsyncResult asyncResult) { - if (IsRequestInstrumented(request)) + // Retrieve the state we stuffed into m_AsyncObject. + Tuple state = (Tuple)s_asyncObjectAccessor(asyncResult); + + // Restore the object in case it was important. + s_asyncObjectModifier(asyncResult, state.Item2); + + try + { + // Call the true callback if it was set. + state.Item3?.Invoke(asyncResult); + } + catch { - this.Write(RequestExceptionName, new { Request = request, Status = status, Exception = exception }); } - } - private bool IsLastResponse(HttpWebRequest request, HttpStatusCode statusCode) - { - if (request.AllowAutoRedirect) - { - if (statusCode == HttpStatusCode.Ambiguous || // 300 - statusCode == HttpStatusCode.Moved || // 301 - statusCode == HttpStatusCode.Redirect || // 302 - statusCode == HttpStatusCode.RedirectMethod || // 303 - statusCode == HttpStatusCode.RedirectKeepVerb || // 307 - (int)statusCode == 308) // 308 Permanent Redirect is not in .NET Framework yet, and so has to be specified this way. + // Access the result of the request. + object result = s_resultAccessor(asyncResult); + + try + { + if (result is Exception ex) + { + s_instance.RaiseExceptionEvent(state.Item1, ex); + } + else { - return s_autoRedirectsAccessor(request) >= request.MaximumAutomaticRedirections; + s_instance.RaiseResponseEvent(state.Item1, (HttpWebResponse)result); } } + catch + { + } - return true; + // Activity.Current should be fine here because the AsyncCallback fires through ExecutionContext but it was easy enough to pass in and this will work even if context wasn't flowed, for some reason. + state.Item4.Stop(); } private static void PrepareReflectionObjects() @@ -744,32 +691,31 @@ private static void PrepareReflectionObjects() s_connectionListField = s_connectionGroupType?.GetField("m_ConnectionList", BindingFlags.Instance | BindingFlags.NonPublic); s_connectionType = systemNetHttpAssembly?.GetType("System.Net.Connection"); s_writeListField = s_connectionType?.GetField("m_WriteList", BindingFlags.Instance | BindingFlags.NonPublic); - s_errorField = s_connectionType?.GetField("m_Error", BindingFlags.Instance | BindingFlags.NonPublic); - s_innerExceptionField = s_connectionType?.GetField("m_InnerException", BindingFlags.Instance | BindingFlags.NonPublic); - s_httpResponseAccessor = CreateFieldGetter("_HttpResponse", BindingFlags.NonPublic | BindingFlags.Instance); - s_autoRedirectsAccessor = CreateFieldGetter("_AutoRedirects", BindingFlags.NonPublic | BindingFlags.Instance); - s_coreResponseAccessor = CreateFieldGetter("_CoreResponse", BindingFlags.NonPublic | BindingFlags.Instance); + s_readAResultAccessor = CreateFieldGetter(typeof(HttpWebRequest), "_ReadAResult", BindingFlags.NonPublic | BindingFlags.Instance); - s_coreResponseDataType = systemNetHttpAssembly?.GetType("System.Net.CoreResponseData"); - if (s_coreResponseDataType != null) + Type lazyAsyncResultType = systemNetHttpAssembly?.GetType("System.Net.LazyAsyncResult"); + if (lazyAsyncResultType != null) { - s_coreStatusCodeAccessor = CreateFieldGetter(s_coreResponseDataType, "m_StatusCode", BindingFlags.Public | BindingFlags.Instance); - s_coreHeadersAccessor = CreateFieldGetter(s_coreResponseDataType, "m_ResponseHeaders", BindingFlags.Public | BindingFlags.Instance); + s_asyncCallbackAccessor = CreateFieldGetter(lazyAsyncResultType, "m_AsyncCallback", BindingFlags.NonPublic | BindingFlags.Instance); + s_asyncCallbackModifier = CreateFieldSetter(lazyAsyncResultType, "m_AsyncCallback", BindingFlags.NonPublic | BindingFlags.Instance); + s_asyncObjectAccessor = CreateFieldGetter(lazyAsyncResultType, "m_AsyncObject", BindingFlags.NonPublic | BindingFlags.Instance); + s_asyncObjectModifier = CreateFieldSetter(lazyAsyncResultType, "m_AsyncObject", BindingFlags.NonPublic | BindingFlags.Instance); + s_resultAccessor = CreateFieldGetter(lazyAsyncResultType, "m_Result", BindingFlags.NonPublic | BindingFlags.Instance); } + // Double checking to make sure we have all the pieces initialized if (s_connectionGroupListField == null || s_connectionGroupType == null || s_connectionListField == null || s_connectionType == null || s_writeListField == null || - s_errorField == null || - s_innerExceptionField == null || - s_httpResponseAccessor == null || - s_autoRedirectsAccessor == null || - s_coreResponseDataType == null || - s_coreStatusCodeAccessor == null || - s_coreHeadersAccessor == null) + s_readAResultAccessor == null || + s_asyncCallbackAccessor == null || + s_asyncCallbackModifier == null || + s_asyncObjectAccessor == null || + s_asyncObjectModifier == null || + s_resultAccessor == null) { // If anything went wrong here, just return false. There is nothing we can do. throw new InvalidOperationException("Unable to initialize all required reflection objects"); @@ -791,42 +737,48 @@ private static void PerformInjection() servicePointTableField.SetValue(null, newTable); } - private static Func CreateFieldGetter(string fieldName, BindingFlags flags) where TClass : class + /// + /// Creates getter for a field defined in private or internal type + /// repesented with classType variable + /// + private static Func CreateFieldGetter(Type classType, string fieldName, BindingFlags flags) { - FieldInfo field = typeof(TClass).GetField(fieldName, flags); + FieldInfo field = classType.GetField(fieldName, flags); if (field != null) { - string methodName = field.ReflectedType.FullName + ".get_" + field.Name; - DynamicMethod getterMethod = new DynamicMethod(methodName, typeof(TField), new[] { typeof(TClass) }, true); + string methodName = classType.FullName + ".get_" + field.Name; + DynamicMethod getterMethod = new DynamicMethod(methodName, typeof(TField), new[] { typeof(object) }, true); ILGenerator generator = getterMethod.GetILGenerator(); generator.Emit(OpCodes.Ldarg_0); + generator.Emit(OpCodes.Castclass, classType); generator.Emit(OpCodes.Ldfld, field); generator.Emit(OpCodes.Ret); - return (Func)getterMethod.CreateDelegate(typeof(Func)); + + return (Func)getterMethod.CreateDelegate(typeof(Func)); } return null; } - /// - /// Creates getter for a field defined in private or internal type + /// Creates setter for a field defined in private or internal type /// repesented with classType variable /// - private static Func CreateFieldGetter(Type classType, string fieldName, BindingFlags flags) + private static Action CreateFieldSetter(Type classType, string fieldName, BindingFlags flags) { FieldInfo field = classType.GetField(fieldName, flags); if (field != null) { - string methodName = classType.FullName + ".get_" + field.Name; - DynamicMethod getterMethod = new DynamicMethod(methodName, typeof(TField), new[] { typeof(object) }, true); - ILGenerator generator = getterMethod.GetILGenerator(); + string methodName = classType.FullName + ".set_" + field.Name; + DynamicMethod setterMethod = new DynamicMethod(methodName, null, new[] { typeof(object), typeof(TField) }, true); + ILGenerator generator = setterMethod.GetILGenerator(); generator.Emit(OpCodes.Ldarg_0); generator.Emit(OpCodes.Castclass, classType); - generator.Emit(OpCodes.Ldfld, field); + generator.Emit(OpCodes.Ldarg_1); + generator.Emit(OpCodes.Stfld, field); generator.Emit(OpCodes.Ret); - return (Func)getterMethod.CreateDelegate(typeof(Func)); + return (Action)setterMethod.CreateDelegate(typeof(Action)); } return null; @@ -838,17 +790,18 @@ private static Func CreateFieldGetter(Type classType, st #region private fields private const string DiagnosticListenerName = "System.Net.Http.Desktop"; - 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 RequestExceptionName = "System.Net.Http.Desktop.HttpRequestOut.Exception"; - private const string RequestStopExName = "System.Net.Http.Desktop.HttpRequestOut.Ex.Stop"; - private const string InitializationFailed = "System.Net.Http.InitializationFailed"; + private const string ActivityName = DiagnosticListenerName + ".HttpRequestOut"; + private const string RequestStartName = ActivityName + ".Start"; + private const string RequestStopName = ActivityName + ".Stop"; + private const string RequestExceptionName = ActivityName + ".Exception"; + private const string InitializationFailed = DiagnosticListenerName + ".InitializationFailed"; private const string RequestIdHeaderName = "Request-Id"; private const string CorrelationContextHeaderName = "Correlation-Context"; private const string TraceParentHeaderName = "traceparent"; private const string TraceStateHeaderName = "tracestate"; + private static readonly AsyncCallback s_asyncCallback = AsyncCallback; + // Fields for controlling initialization of the HttpHandlerDiagnosticListener singleton private bool _initialized = false; @@ -858,14 +811,12 @@ private static Func CreateFieldGetter(Type classType, st private static FieldInfo s_connectionListField; private static Type s_connectionType; private static FieldInfo s_writeListField; - private static FieldInfo s_errorField; - private static FieldInfo s_innerExceptionField; - private static Func s_httpResponseAccessor; - private static Func s_autoRedirectsAccessor; - private static Func s_coreResponseAccessor; - private static Func s_coreStatusCodeAccessor; - private static Func s_coreHeadersAccessor; - private static Type s_coreResponseDataType; + private static Func s_readAResultAccessor; + private static Func s_asyncCallbackAccessor; + private static Action s_asyncCallbackModifier; + private static Func s_asyncObjectAccessor; + private static Action s_asyncObjectModifier; + private static Func s_resultAccessor; #endregion } diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 9abfe61fa52789..67e129facbe785 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -8,7 +8,6 @@ using System.Net; using System.Net.Http; using System.Reflection; -using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; using Xunit; @@ -220,12 +219,12 @@ public async Task TestW3CHeadersWithoutContent() KeyValuePair stopEvent; Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Ex.Stop", stopEvent.Key); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); Assert.NotNull(stopRequest); - HttpStatusCode status = ReadPublicProperty(stopEvent.Value, "StatusCode"); - Assert.Equal(HttpStatusCode.OK, status); + HttpWebResponse stopResponse = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(stopResponse); } } finally @@ -293,13 +292,8 @@ public async Task DoNotInjectRequestIdWhenPresent() (await client.SendAsync(request)).Dispose(); } - Assert.Equal(1, eventRecords.Records.Count()); // Only Stop event is sent. - - // Check to make sure: The first record must be a request, the next record must be a response. - Assert.True(eventRecords.Records.TryDequeue(out var evnt)); - HttpWebRequest startRequest = ReadPublicProperty(evnt.Value, "Request"); - Assert.NotNull(startRequest); - Assert.Equal("|rootId.1.", startRequest.Headers["Request-Id"]); + // No events are sent. + Assert.Equal(0, eventRecords.Records.Count()); } } @@ -321,14 +315,8 @@ public async Task DoNotInjectTraceParentWhenPresent() (await client.SendAsync(request)).Dispose(); } - Assert.Equal(1, eventRecords.Records.Count()); // Only Stop event is sent. - - // Check to make sure: The first record must be a request, the next record must be a response. - Assert.True(eventRecords.Records.TryDequeue(out var evnt)); - HttpWebRequest startRequest = ReadPublicProperty(evnt.Value, "Request"); - Assert.NotNull(startRequest); - - Assert.Equal("00-abcdef0123456789abcdef0123456789-abcdef0123456789-01", startRequest.Headers["traceparent"]); + // No events are sent. + Assert.Equal(0, eventRecords.Records.Count()); } } finally @@ -363,14 +351,11 @@ public async Task TestResponseWithoutContentEvents() KeyValuePair stopEvent; Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); - Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Ex.Stop", stopEvent.Key); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); Assert.Equal(startRequest, stopRequest); - HttpStatusCode status = ReadPublicProperty(stopEvent.Value, "StatusCode"); - Assert.Equal(HttpStatusCode.OK, status); - - WebHeaderCollection headers = ReadPublicProperty(stopEvent.Value, "Headers"); - Assert.NotNull(headers); + HttpWebResponse stopResponse = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(stopResponse); } } @@ -427,8 +412,6 @@ await Assert.ThrowsAsync( Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Exception", exceptionEvent.Key); HttpWebRequest exceptionRequest = ReadPublicProperty(exceptionEvent.Value, "Request"); Assert.Equal(startRequest, exceptionRequest); - WebExceptionStatus? exceptionStatus = ReadPublicProperty(exceptionEvent.Value, "Status"); - Assert.Equal(WebExceptionStatus.NameResolutionFailure, exceptionStatus); Exception exceptionException = ReadPublicProperty(exceptionEvent.Value, "Exception"); Assert.Equal(webException, exceptionException); } @@ -457,6 +440,74 @@ public async Task TestCanceledRequest() } } + /// + /// Test request connection exception: reflection hook does not throw + /// + [OuterLoop] + [Fact] + public async Task TestSecureTransportFailureRequest() + { + using (var eventRecords = new EventObserverAndRecorder()) + { + using (var client = new HttpClient()) + { + var ex = await Assert.ThrowsAnyAsync(() => client.GetAsync(Configuration.Http.ExpiredCertRemoteServer)); + Assert.True(ex is HttpRequestException); + } + + // We should have one Start event, no Stop event, and one Exception event. + Assert.Equal(2, eventRecords.Records.Count()); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Exception"))); + } + } + + /// + /// Test request connection retry: reflection hook does not throw + /// + [OuterLoop] + [Fact] + public async Task TestSecureTransportRetryFailureRequest() + { + // This test sends an https request to an endpoint only set up for http. + // It should retry. What we want to test for is 1 start, 1 exception event even + // though multiple are actually sent. + + using (HttpListener server = new HttpListener()) + { + server.Prefixes.Add("http://localhost:8018/dotnet/tests/"); + server.Start(); + + _ = Task.Run(() => + { + try + { + // Request should never come into here. + var context = server.GetContext(); + context.Response.StatusCode = (int)HttpStatusCode.NoContent; + context.Response.Close(); + } + catch (HttpListenerException) + { + } + }); + + using (var eventRecords = new EventObserverAndRecorder()) + { + using (var client = new HttpClient()) + { + var ex = await Assert.ThrowsAnyAsync(() => client.GetAsync("https://localhost:8018/dotnet/tests")); + Assert.True(ex is HttpRequestException); + } + + // We should have one Start event, no Stop event, and one Exception event. + Assert.Equal(2, eventRecords.Records.Count()); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Exception"))); + } + } + } + /// /// Test Request-Id and Correlation-Context headers injection /// @@ -541,6 +592,10 @@ bool IsEnabled(string evnt, object arg1, object arg2) { Assert.True(evnt == "System.Net.Http.Desktop.HttpRequestOut.Start"); } + else if (eventNumber == 2) + { + Assert.True(evnt == "System.Net.Http.Desktop.HttpRequestOut.Stop"); + } eventNumber++; return true; @@ -552,7 +607,7 @@ bool IsEnabled(string evnt, object arg1, object arg2) { (await client.GetAsync(Configuration.Http.RemoteEchoServer)).Dispose(); } - Assert.Equal(2, eventNumber); + Assert.Equal(3, eventNumber); } } From e243490b71ac655aa4b828f43ca88747a6078e8a Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Tue, 24 Mar 2020 19:42:03 -0700 Subject: [PATCH 5/8] Added HttpWebRequest specific tests. Switched hook state to fix EndGetResponse blowing up with modified object. --- .../HttpHandlerDiagnosticListener.cs | 22 +-- .../HttpHandlerDiagnosticListenerTests.cs | 128 ++++++++++++++++++ 2 files changed, 139 insertions(+), 11 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 31f6d870cbd028..0be0994cbee59b 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -559,8 +559,8 @@ private void RaiseRequestEvent(HttpWebRequest request) object asyncContext = s_readAResultAccessor(request); - // Step 1: Hook request._ReadAResult.m_AsyncObject to store the state (request + callback + object + activity) we will need later. - s_asyncObjectModifier(asyncContext, new Tuple(request, s_asyncObjectAccessor(asyncContext), s_asyncCallbackAccessor(asyncContext), activity)); + // Step 1: Hook request._ReadAResult.m_AsyncState to store the state (request + callback + state + activity) we will need later. + s_asyncStateModifier(asyncContext, new Tuple(request, s_asyncStateAccessor(asyncContext), s_asyncCallbackAccessor(asyncContext), activity)); // Step 2: Hook request._ReadAResult.m_AsyncCallback so we can fire our events when the request is complete. s_asyncCallbackModifier(asyncContext, s_asyncCallback); @@ -643,11 +643,11 @@ private static void InstrumentRequest(HttpWebRequest request, Activity activity) private static void AsyncCallback(IAsyncResult asyncResult) { - // Retrieve the state we stuffed into m_AsyncObject. - Tuple state = (Tuple)s_asyncObjectAccessor(asyncResult); + // Retrieve the state we stuffed into m_AsyncState. + Tuple state = (Tuple)s_asyncStateAccessor(asyncResult); // Restore the object in case it was important. - s_asyncObjectModifier(asyncResult, state.Item2); + s_asyncStateModifier(asyncResult, state.Item2); try { @@ -699,8 +699,8 @@ private static void PrepareReflectionObjects() { s_asyncCallbackAccessor = CreateFieldGetter(lazyAsyncResultType, "m_AsyncCallback", BindingFlags.NonPublic | BindingFlags.Instance); s_asyncCallbackModifier = CreateFieldSetter(lazyAsyncResultType, "m_AsyncCallback", BindingFlags.NonPublic | BindingFlags.Instance); - s_asyncObjectAccessor = CreateFieldGetter(lazyAsyncResultType, "m_AsyncObject", BindingFlags.NonPublic | BindingFlags.Instance); - s_asyncObjectModifier = CreateFieldSetter(lazyAsyncResultType, "m_AsyncObject", BindingFlags.NonPublic | BindingFlags.Instance); + s_asyncStateAccessor = CreateFieldGetter(lazyAsyncResultType, "m_AsyncState", BindingFlags.NonPublic | BindingFlags.Instance); + s_asyncStateModifier = CreateFieldSetter(lazyAsyncResultType, "m_AsyncState", BindingFlags.NonPublic | BindingFlags.Instance); s_resultAccessor = CreateFieldGetter(lazyAsyncResultType, "m_Result", BindingFlags.NonPublic | BindingFlags.Instance); } @@ -713,8 +713,8 @@ private static void PrepareReflectionObjects() s_readAResultAccessor == null || s_asyncCallbackAccessor == null || s_asyncCallbackModifier == null || - s_asyncObjectAccessor == null || - s_asyncObjectModifier == null || + s_asyncStateAccessor == null || + s_asyncStateModifier == null || s_resultAccessor == null) { // If anything went wrong here, just return false. There is nothing we can do. @@ -814,8 +814,8 @@ private static Action CreateFieldSetter(Type classType, private static Func s_readAResultAccessor; private static Func s_asyncCallbackAccessor; private static Action s_asyncCallbackModifier; - private static Func s_asyncObjectAccessor; - private static Action s_asyncObjectModifier; + private static Func s_asyncStateAccessor; + private static Action s_asyncStateModifier; private static Func s_resultAccessor; #endregion diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 67e129facbe785..0997314934b9d7 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -145,6 +145,134 @@ public async Task TestBasicReceiveAndResponseEvents() } } + [OuterLoop] + [Fact] + public void TestBasicReceiveAndResponseWebRequestSyncEvents() + { + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyHeaders(startRequest); + })) + { + { + // Send a random Http request to generate some events + var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); + + using var webResponse = (HttpWebResponse)webRequest.GetResponse(); + } + + // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + + // Check to make sure: The first record must be a request, the next record must be a response. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyHeaders(startRequest); + + KeyValuePair stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); + Assert.Equal(startRequest, stopRequest); + HttpWebResponse response = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(response); + } + } + + [OuterLoop] + [Fact] + public void TestBasicReceiveAndResponseWebRequestAsyncEvents() + { + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyHeaders(startRequest); + })) + { + { + // Send a random Http request to generate some events + var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); + + var asyncResult = webRequest.BeginGetResponse(null, null); + + asyncResult.AsyncWaitHandle.WaitOne(); + + webRequest.EndGetResponse(asyncResult); + } + + // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + + // Check to make sure: The first record must be a request, the next record must be a response. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyHeaders(startRequest); + + KeyValuePair stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); + Assert.Equal(startRequest, stopRequest); + HttpWebResponse response = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(response); + } + } + + [OuterLoop] + [Fact] + public void TestBasicReceiveAndResponseWebRequestAsyncWithCallbackEvents() + { + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyHeaders(startRequest); + })) + { + bool callbackCalled = false; + + using EventWaitHandle CallbackHandle = new EventWaitHandle(false, EventResetMode.ManualReset); + + { + // Send a random Http request to generate some events + var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); + + int state = 18; + var asyncResult = webRequest.BeginGetResponse( + ar => + { + callbackCalled = true; + Assert.Equal(state, (int)ar.AsyncState); + CallbackHandle.Set(); + }, + state); + + asyncResult.AsyncWaitHandle.WaitOne(); + + using var webResponse = webRequest.EndGetResponse(asyncResult); + } + + CallbackHandle.WaitOne(TimeSpan.FromSeconds(10)); // Callback can fire on its own thread, give it a chance to execute. + + Assert.True(callbackCalled); + + // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + } + } + [OuterLoop] [Fact] public async Task TestW3CHeaders() From a4e9e4695cd0d1c570ad0dbe33855c32ac93883b Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 25 Mar 2020 10:56:03 -0700 Subject: [PATCH 6/8] Added a test for WebRequest.GetResponseAsync method. --- .../HttpHandlerDiagnosticListenerTests.cs | 47 +++++++++++++++++-- 1 file changed, 43 insertions(+), 4 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 0997314934b9d7..82c71dee39f6cf 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -161,7 +161,7 @@ public void TestBasicReceiveAndResponseWebRequestSyncEvents() // Send a random Http request to generate some events var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); - using var webResponse = (HttpWebResponse)webRequest.GetResponse(); + using var webResponse = webRequest.GetResponse(); } // We should have exactly one Start and one Stop event @@ -186,7 +186,7 @@ public void TestBasicReceiveAndResponseWebRequestSyncEvents() [OuterLoop] [Fact] - public void TestBasicReceiveAndResponseWebRequestAsyncEvents() + public void TestBasicReceiveAndResponseWebRequestAsyncResultEvents() { using (var eventRecords = new EventObserverAndRecorder(e => { @@ -204,7 +204,7 @@ public void TestBasicReceiveAndResponseWebRequestAsyncEvents() asyncResult.AsyncWaitHandle.WaitOne(); - webRequest.EndGetResponse(asyncResult); + using var webResponse = webRequest.EndGetResponse(asyncResult); } // We should have exactly one Start and one Stop event @@ -229,7 +229,7 @@ public void TestBasicReceiveAndResponseWebRequestAsyncEvents() [OuterLoop] [Fact] - public void TestBasicReceiveAndResponseWebRequestAsyncWithCallbackEvents() + public void TestBasicReceiveAndResponseWebRequestAsyncResultWithCallbackEvents() { using (var eventRecords = new EventObserverAndRecorder(e => { @@ -273,6 +273,45 @@ public void TestBasicReceiveAndResponseWebRequestAsyncWithCallbackEvents() } } + [OuterLoop] + [Fact] + public async Task TestBasicReceiveAndResponseWebRequestAsyncEvents() + { + using (var eventRecords = new EventObserverAndRecorder(e => + { + // Verify header is available when start event is fired. + HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); + Assert.NotNull(startRequest); + VerifyHeaders(startRequest); + })) + { + { + // Send a random Http request to generate some events + var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); + + using var webResponse = await webRequest.GetResponseAsync(); + } + + // We should have exactly one Start and one Stop event + Assert.Equal(2, eventRecords.Records.Count); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); + Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Stop"))); + + // Check to make sure: The first record must be a request, the next record must be a response. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyHeaders(startRequest); + + KeyValuePair stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); + Assert.Equal(startRequest, stopRequest); + HttpWebResponse response = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(response); + } + } + [OuterLoop] [Fact] public async Task TestW3CHeaders() From 85005292f08a4b1f124b908c0750d2045f6afd50 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 26 Mar 2020 11:04:16 -0700 Subject: [PATCH 7/8] Fixed event ordering and race condition where response gets disposed on another thread. --- .../HttpHandlerDiagnosticListener.cs | 219 +++++++++++++++--- .../HttpHandlerDiagnosticListenerTests.cs | 42 ++-- 2 files changed, 217 insertions(+), 44 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 0be0994cbee59b..4eaff52e5199f4 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -646,30 +646,42 @@ private static void AsyncCallback(IAsyncResult asyncResult) // Retrieve the state we stuffed into m_AsyncState. Tuple state = (Tuple)s_asyncStateAccessor(asyncResult); - // Restore the object in case it was important. - s_asyncStateModifier(asyncResult, state.Item2); + AsyncCallback asyncCallback = state.Item3; try { - // Call the true callback if it was set. - state.Item3?.Invoke(asyncResult); - } - catch - { - } - - // Access the result of the request. - object result = s_resultAccessor(asyncResult); + // Access the result of the request. + object result = s_resultAccessor(asyncResult); - try - { if (result is Exception ex) { s_instance.RaiseExceptionEvent(state.Item1, ex); } else { - s_instance.RaiseResponseEvent(state.Item1, (HttpWebResponse)result); + HttpWebResponse response = (HttpWebResponse)result; + + if (asyncCallback == null && s_isContextAwareResultChecker(asyncResult)) + { + // For async calls (where asyncResult is ContextAwareResult)... + // If no callback was set assume the user is manually calling BeginGetResponse & EndGetResponse + // in which case they could dispose the HttpWebResponse before our listeners have a chance to work with it. + // Disposed HttpWebResponse throws when accessing properties, so let's make a copy of the data to ensure that doesn't happen. + + using HttpWebResponse responseCopy = s_httpWebResponseCtor( + new object[] + { + s_uriAccessor(response), s_verbAccessor(response), s_coreResponseDataAccessor(response), s_mediaTypeAccessor(response), + s_usesProxySemanticsAccessor(response), DecompressionMethods.None, + s_isWebSocketResponseAccessor(response), s_connectionGroupNameAccessor(response) + }); + + s_instance.RaiseResponseEvent(state.Item1, responseCopy); + } + else + { + s_instance.RaiseResponseEvent(state.Item1, response); + } } } catch @@ -678,15 +690,21 @@ private static void AsyncCallback(IAsyncResult asyncResult) // Activity.Current should be fine here because the AsyncCallback fires through ExecutionContext but it was easy enough to pass in and this will work even if context wasn't flowed, for some reason. state.Item4.Stop(); + + // Restore the state in case anyone downstream is reliant on it. + s_asyncStateModifier(asyncResult, state.Item2); + + // Fire the user's callback, if it was set. No try/catch so calling HttpWebRequest can abort on failure. + asyncCallback?.Invoke(asyncResult); } private static void PrepareReflectionObjects() { // At any point, if the operation failed, it should just throw. The caller should catch all exceptions and swallow. - // First step: Get all the reflection objects we will ever need. - Assembly systemNetHttpAssembly = typeof(ServicePoint).Assembly; - s_connectionGroupListField = typeof(ServicePoint).GetField("m_ConnectionGroupList", BindingFlags.Instance | BindingFlags.NonPublic); + Type servicePointType = typeof(ServicePoint); + Assembly systemNetHttpAssembly = servicePointType.Assembly; + s_connectionGroupListField = servicePointType.GetField("m_ConnectionGroupList", BindingFlags.Instance | BindingFlags.NonPublic); s_connectionGroupType = systemNetHttpAssembly?.GetType("System.Net.ConnectionGroup"); s_connectionListField = s_connectionGroupType?.GetField("m_ConnectionList", BindingFlags.Instance | BindingFlags.NonPublic); s_connectionType = systemNetHttpAssembly?.GetType("System.Net.Connection"); @@ -694,6 +712,23 @@ private static void PrepareReflectionObjects() s_readAResultAccessor = CreateFieldGetter(typeof(HttpWebRequest), "_ReadAResult", BindingFlags.NonPublic | BindingFlags.Instance); + // Double checking to make sure we have all the pieces initialized + if (s_connectionGroupListField == null || + s_connectionGroupType == null || + s_connectionListField == null || + s_connectionType == null || + s_writeListField == null || + s_readAResultAccessor == null || + !PrepareAsyncResultReflectionObjects(systemNetHttpAssembly) || + !PrepareHttpWebResponseReflectionObjects(systemNetHttpAssembly)) + { + // If anything went wrong here, just return false. There is nothing we can do. + throw new InvalidOperationException("Unable to initialize all required reflection objects"); + } + } + + private static bool PrepareAsyncResultReflectionObjects(Assembly systemNetHttpAssembly) + { Type lazyAsyncResultType = systemNetHttpAssembly?.GetType("System.Net.LazyAsyncResult"); if (lazyAsyncResultType != null) { @@ -704,22 +739,60 @@ private static void PrepareReflectionObjects() s_resultAccessor = CreateFieldGetter(lazyAsyncResultType, "m_Result", BindingFlags.NonPublic | BindingFlags.Instance); } - // Double checking to make sure we have all the pieces initialized - if (s_connectionGroupListField == null || - s_connectionGroupType == null || - s_connectionListField == null || - s_connectionType == null || - s_writeListField == null || - s_readAResultAccessor == null || - s_asyncCallbackAccessor == null || - s_asyncCallbackModifier == null || - s_asyncStateAccessor == null || - s_asyncStateModifier == null || - s_resultAccessor == null) + Type contextAwareResultType = systemNetHttpAssembly?.GetType("System.Net.ContextAwareResult"); + if (contextAwareResultType != null) { - // If anything went wrong here, just return false. There is nothing we can do. - throw new InvalidOperationException("Unable to initialize all required reflection objects"); + s_isContextAwareResultChecker = CreateTypeChecker(contextAwareResultType); } + + return s_asyncCallbackAccessor != null + && s_asyncCallbackModifier != null + && s_asyncStateAccessor != null + && s_asyncStateModifier != null + && s_resultAccessor != null + && s_isContextAwareResultChecker != null; + } + + private static bool PrepareHttpWebResponseReflectionObjects(Assembly systemNetHttpAssembly) + { + Type knownHttpVerbType = systemNetHttpAssembly?.GetType("System.Net.KnownHttpVerb"); + Type coreResponseData = systemNetHttpAssembly?.GetType("System.Net.CoreResponseData"); + + if (knownHttpVerbType != null && coreResponseData != null) + { + ConstructorInfo ctor = typeof(HttpWebResponse).GetConstructor( + BindingFlags.NonPublic | BindingFlags.Instance, + null, + new Type[] + { + typeof(Uri), knownHttpVerbType, coreResponseData, typeof(string), + typeof(bool), typeof(DecompressionMethods), + typeof(bool), typeof(string) + }, + null); + + if (ctor != null) + { + s_httpWebResponseCtor = CreateTypeInstance(ctor); + } + } + + s_uriAccessor = CreateFieldGetter("m_Uri", BindingFlags.NonPublic | BindingFlags.Instance); + s_verbAccessor = CreateFieldGetter("m_Verb", BindingFlags.NonPublic | BindingFlags.Instance); + s_mediaTypeAccessor = CreateFieldGetter("m_MediaType", BindingFlags.NonPublic | BindingFlags.Instance); + s_usesProxySemanticsAccessor = CreateFieldGetter("m_UsesProxySemantics", BindingFlags.NonPublic | BindingFlags.Instance); + s_coreResponseDataAccessor = CreateFieldGetter("m_CoreResponseData", BindingFlags.NonPublic | BindingFlags.Instance); + s_isWebSocketResponseAccessor = CreateFieldGetter("m_IsWebSocketResponse", BindingFlags.NonPublic | BindingFlags.Instance); + s_connectionGroupNameAccessor = CreateFieldGetter("m_ConnectionGroupName", BindingFlags.NonPublic | BindingFlags.Instance); + + return s_httpWebResponseCtor != null + && s_uriAccessor != null + && s_verbAccessor != null + && s_mediaTypeAccessor != null + && s_usesProxySemanticsAccessor != null + && s_coreResponseDataAccessor != null + && s_isWebSocketResponseAccessor != null + && s_connectionGroupNameAccessor != null; } private static void PerformInjection() @@ -737,6 +810,23 @@ private static void PerformInjection() servicePointTableField.SetValue(null, newTable); } + private static Func CreateFieldGetter(string fieldName, BindingFlags flags) where TClass : class + { + FieldInfo field = typeof(TClass).GetField(fieldName, flags); + if (field != null) + { + string methodName = field.ReflectedType.FullName + ".get_" + field.Name; + DynamicMethod getterMethod = new DynamicMethod(methodName, typeof(TField), new[] { typeof(TClass) }, true); + ILGenerator generator = getterMethod.GetILGenerator(); + generator.Emit(OpCodes.Ldarg_0); + generator.Emit(OpCodes.Ldfld, field); + generator.Emit(OpCodes.Ret); + return (Func)getterMethod.CreateDelegate(typeof(Func)); + } + + return null; + } + /// /// Creates getter for a field defined in private or internal type /// repesented with classType variable @@ -784,6 +874,60 @@ private static Action CreateFieldSetter(Type classType, return null; } + /// + /// Creates an "is" method for the private or internal type. + /// + private static Func CreateTypeChecker(Type classType) + { + string methodName = classType.FullName + ".typeCheck"; + DynamicMethod setterMethod = new DynamicMethod(methodName, typeof(bool), new[] { typeof(object) }, true); + ILGenerator generator = setterMethod.GetILGenerator(); + generator.Emit(OpCodes.Ldarg_0); + generator.Emit(OpCodes.Isinst, classType); + generator.Emit(OpCodes.Ldnull); + generator.Emit(OpCodes.Cgt_Un); + generator.Emit(OpCodes.Ret); + + return (Func)setterMethod.CreateDelegate(typeof(Func)); + } + + /// + /// Creates an instance of T using a private or internal ctor. + /// + private static Func CreateTypeInstance(ConstructorInfo constructorInfo) + { + Type classType = typeof(T); + string methodName = classType.FullName + ".ctor"; + DynamicMethod setterMethod = new DynamicMethod(methodName, classType, new Type[] { typeof(object[]) }, true); + ILGenerator generator = setterMethod.GetILGenerator(); + + ParameterInfo[] ctorParams = constructorInfo.GetParameters(); + for (int i = 0; i < ctorParams.Length; i++) + { + generator.Emit(OpCodes.Ldarg_0); + switch (i) + { + case 0: generator.Emit(OpCodes.Ldc_I4_0); break; + case 1: generator.Emit(OpCodes.Ldc_I4_1); break; + case 2: generator.Emit(OpCodes.Ldc_I4_2); break; + case 3: generator.Emit(OpCodes.Ldc_I4_3); break; + case 4: generator.Emit(OpCodes.Ldc_I4_4); break; + case 5: generator.Emit(OpCodes.Ldc_I4_5); break; + case 6: generator.Emit(OpCodes.Ldc_I4_6); break; + case 7: generator.Emit(OpCodes.Ldc_I4_7); break; + case 8: generator.Emit(OpCodes.Ldc_I4_8); break; + default: generator.Emit(OpCodes.Ldc_I4, i); break; + } + generator.Emit(OpCodes.Ldelem_Ref); + Type paramType = ctorParams[i].ParameterType; + generator.Emit(paramType.IsValueType ? OpCodes.Unbox_Any : OpCodes.Castclass, paramType); + } + generator.Emit(OpCodes.Newobj, constructorInfo); + generator.Emit(OpCodes.Ret); + + return (Func)setterMethod.CreateDelegate(typeof(Func)); + } + #endregion internal static readonly HttpHandlerDiagnosticListener s_instance = new HttpHandlerDiagnosticListener(); @@ -812,11 +956,24 @@ private static Action CreateFieldSetter(Type classType, private static Type s_connectionType; private static FieldInfo s_writeListField; private static Func s_readAResultAccessor; + + // LazyAsyncResult & ContextAwareResult private static Func s_asyncCallbackAccessor; private static Action s_asyncCallbackModifier; private static Func s_asyncStateAccessor; private static Action s_asyncStateModifier; private static Func s_resultAccessor; + private static Func s_isContextAwareResultChecker; + + // HttpWebResponse + private static Func s_httpWebResponseCtor; + private static Func s_uriAccessor; + private static Func s_verbAccessor; + private static Func s_mediaTypeAccessor; + private static Func s_usesProxySemanticsAccessor; + private static Func s_coreResponseDataAccessor; + private static Func s_isWebSocketResponseAccessor; + private static Func s_connectionGroupNameAccessor; #endregion } diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 82c71dee39f6cf..949c3a5e404020 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -161,7 +161,7 @@ public void TestBasicReceiveAndResponseWebRequestSyncEvents() // Send a random Http request to generate some events var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); - using var webResponse = webRequest.GetResponse(); + webRequest.GetResponse().Dispose(); } // We should have exactly one Start and one Stop event @@ -188,12 +188,27 @@ public void TestBasicReceiveAndResponseWebRequestSyncEvents() [Fact] public void TestBasicReceiveAndResponseWebRequestAsyncResultEvents() { + using EventWaitHandle CallbackHandle = new EventWaitHandle(false, EventResetMode.ManualReset); + + HttpStatusCode? responseStatusCode = null; + using (var eventRecords = new EventObserverAndRecorder(e => { - // Verify header is available when start event is fired. - HttpWebRequest startRequest = ReadPublicProperty(e.Value, "Request"); - Assert.NotNull(startRequest); - VerifyHeaders(startRequest); + if (e.Key.EndsWith("Stop")) + { + // Make sure response instance does not get disposed while we're working on it. + Thread.Sleep(TimeSpan.FromSeconds(5)); + HttpWebResponse response = ReadPublicProperty(e.Value, "Response"); + Assert.NotNull(response); + try + { + responseStatusCode = response.StatusCode; + } + catch + { + } + CallbackHandle.Set(); + } })) { { @@ -202,11 +217,14 @@ public void TestBasicReceiveAndResponseWebRequestAsyncResultEvents() var asyncResult = webRequest.BeginGetResponse(null, null); - asyncResult.AsyncWaitHandle.WaitOne(); - - using var webResponse = webRequest.EndGetResponse(asyncResult); + webRequest.EndGetResponse(asyncResult).Dispose(); } + CallbackHandle.WaitOne(TimeSpan.FromSeconds(10)); // Give the callback time to complete. + + Assert.True(responseStatusCode.HasValue); + Assert.Equal(HttpStatusCode.OK, responseStatusCode); + // We should have exactly one Start and one Stop event Assert.Equal(2, eventRecords.Records.Count); Assert.Equal(1, eventRecords.Records.Count(rec => rec.Key.EndsWith("Start"))); @@ -257,12 +275,10 @@ public void TestBasicReceiveAndResponseWebRequestAsyncResultWithCallbackEvents() }, state); - asyncResult.AsyncWaitHandle.WaitOne(); - - using var webResponse = webRequest.EndGetResponse(asyncResult); + webRequest.EndGetResponse(asyncResult).Dispose(); } - CallbackHandle.WaitOne(TimeSpan.FromSeconds(10)); // Callback can fire on its own thread, give it a chance to execute. + CallbackHandle.WaitOne(TimeSpan.FromSeconds(10)); // Callback fires on its own thread, give it a chance to execute. Assert.True(callbackCalled); @@ -289,7 +305,7 @@ public async Task TestBasicReceiveAndResponseWebRequestAsyncEvents() // Send a random Http request to generate some events var webRequest = (HttpWebRequest)WebRequest.Create(Configuration.Http.RemoteEchoServer); - using var webResponse = await webRequest.GetResponseAsync(); + (await webRequest.GetResponseAsync()).Dispose(); } // We should have exactly one Start and one Stop event From aa2ee320a03a0e108a857a59814aec324c25b59e Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Mon, 30 Mar 2020 16:25:53 -0700 Subject: [PATCH 8/8] Code review feedback. --- .../src/System/Diagnostics/Activity.cs | 2 +- .../HttpHandlerDiagnosticListener.cs | 8 +++- .../HttpHandlerDiagnosticListenerTests.cs | 38 ++++++++++++++++++- 3 files changed, 44 insertions(+), 4 deletions(-) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs index b98571feffb22d..729282045afc72 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs @@ -48,7 +48,7 @@ public partial class Activity /// /// Normally if the ParentID is defined, the format of that is used to determine the /// format used by the Activity. However if ForceDefaultFormat is set to true, the - /// ID format will always be the DefaultIdFormat even if the ParentID is define and is + /// ID format will always be the DefaultIdFormat even if the ParentID is defined and is /// a different format. /// public static bool ForceDefaultIdFormat { get; set; } diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs index 4eaff52e5199f4..516cd137d522c8 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs @@ -593,7 +593,13 @@ private void RaiseExceptionEvent(HttpWebRequest request, Exception exception) private bool IsRequestInstrumented(HttpWebRequest request) { - return request.Headers.Get(TraceParentHeaderName) != null || request.Headers.Get(RequestIdHeaderName) != null; + ActivityIdFormat Format = Activity.ForceDefaultIdFormat + ? Activity.DefaultIdFormat + : (Activity.Current?.IdFormat ?? Activity.DefaultIdFormat); + + return Format == ActivityIdFormat.W3C + ? request.Headers.Get(TraceParentHeaderName) != null + : request.Headers.Get(RequestIdHeaderName) != null; } private static void InstrumentRequest(HttpWebRequest request, Activity activity) diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs index 949c3a5e404020..a20285210d31d2 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/tests/HttpHandlerDiagnosticListenerTests.cs @@ -480,6 +480,40 @@ public async Task DoNotInjectRequestIdWhenPresent() } } + [OuterLoop] + [Fact] + public async Task InjectTraceIdWhenRequestIdIsPresentButTraceFormatIsW3C() + { + Activity.DefaultIdFormat = ActivityIdFormat.W3C; + + using (var eventRecords = new EventObserverAndRecorder()) + { + // Send a random Http request to generate some events + using (var client = new HttpClient()) + using (var request = new HttpRequestMessage(HttpMethod.Get, Configuration.Http.RemoteEchoServer)) + { + request.Headers.Add("Request-Id", "|rootId.1."); + (await client.SendAsync(request)).Dispose(); + } + + Assert.Equal(2, eventRecords.Records.Count()); + + // Check to make sure: The first record must be a request, the next record must be a response. + HttpWebRequest startRequest = AssertFirstEventWasStart(eventRecords); + + VerifyW3CHeaders(startRequest, expectedRequestIdHeaderValue: "|rootId.1."); + + KeyValuePair stopEvent; + Assert.True(eventRecords.Records.TryDequeue(out stopEvent)); + Assert.Equal("System.Net.Http.Desktop.HttpRequestOut.Stop", stopEvent.Key); + HttpWebRequest stopRequest = ReadPublicProperty(stopEvent.Value, "Request"); + Assert.NotNull(stopRequest); + + HttpWebResponse stopResponse = ReadPublicProperty(stopEvent.Value, "Response"); + Assert.NotNull(stopResponse); + } + } + [OuterLoop] [Fact] public async Task DoNotInjectTraceParentWhenPresent() @@ -998,13 +1032,13 @@ private static void VerifyHeaders(HttpWebRequest startRequest) Assert.Null(startRequest.Headers["tracestate"]); } - private static void VerifyW3CHeaders(HttpWebRequest startRequest) + private static void VerifyW3CHeaders(HttpWebRequest startRequest, string expectedRequestIdHeaderValue = null) { var traceparent = startRequest.Headers["traceparent"]; Assert.NotNull(traceparent); Assert.Matches("^[0-9a-f][0-9a-f]-[0-9a-f]{32}-[0-9a-f]{16}-[0-9a-f][0-9a-f]$", traceparent); Assert.Null(startRequest.Headers["tracestate"]); - Assert.Null(startRequest.Headers["Request-Id"]); + Assert.Equal(expectedRequestIdHeaderValue, startRequest.Headers["Request-Id"]); } ///