Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

System.Diagnostics.DiagnosticSource.HttpHandlerDiagnosticListener bug fixes & edge cases #33732

Closed
wants to merge 9 commits into from
Closed

System.Diagnostics.DiagnosticSource.HttpHandlerDiagnosticListener bug fixes & edge cases #33732

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
0c7187a
Improved HttpHandlerDiagnosticListener's handling of exceptions throw…
CodeBlanch Mar 18, 2020
af40415
Fixed a few style issues. One small optimization.
CodeBlanch Mar 18, 2020
687a020
Merge branch 'master' into HttpHandlerDiagnosticListener-exceptions
CodeBlanch Mar 19, 2020
f54a7c9
Code review.
CodeBlanch Mar 19, 2020
b6ac3ac
New design hooking into AsyncCallback.
CodeBlanch Mar 25, 2020
e243490
Added HttpWebRequest specific tests. Switched hook state to fix EndGe…
CodeBlanch Mar 25, 2020
a4e9e46
Added a test for WebRequest.GetResponseAsync method.
CodeBlanch Mar 25, 2020
8500529
Fixed event ordering and race condition where response gets disposed …
CodeBlanch Mar 26, 2020
aa2ee32
Code review feedback.
CodeBlanch Mar 30, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
139 changes: 90 additions & 49 deletions ...stem.Diagnostics.DiagnosticSource/src/System/Diagnostics/HttpHandlerDiagnosticListener.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -280,7 +279,7 @@ public override object this[object key]
/// </summary>
private class ArrayListWrapper : ArrayList
{
private ArrayList _list;
private readonly ArrayList _list;

public override int Capacity
{
Expand Down Expand Up @@ -496,7 +495,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);
}
Expand All @@ -514,22 +513,45 @@ public override int Add(object value)
/// </summary>
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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't notice any test that would fail if this code got reverted, I would add one.

Copy link
Contributor Author

@CodeBlanch CodeBlanch Mar 19, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If reverted TestCanceledRequest will fail because no Exception event is fired. To cancel the request it does this: new EventObserverAndRecorder(_ => { cts.Cancel(); })

Before:

  1. m_WriteList.Add is called
  2. Start event fired
  3. User code called (cts.Cancel)
  4. Request is aborted
  5. Connection looks for an active request in m_WriteList, finds nothing (https://referencesource.microsoft.com/#system/net/System/Net/_Connection.cs,2816). If it finds something a lot more code happens including a potential call to m_WriteList.Clear. No Exception event is fired
  6. Request is added to the ArrayList. It might be leaked at this point, no cleanup will happen because abort/cleanup has already completed?

After:

  1. m_WriteList.Add is called
  2. Request is added to the ArrayList
  3. Start event fired
  4. User code called (cts.Cancel)
  5. Request is aborted
  6. Connection looks for a request to remove in m_WriteList, successfully finds the active one. Is able to do its cleanup which causes the Exception event to fire correctly


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)
Expand All @@ -538,35 +560,40 @@ 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?;
if (error.HasValue)
{
s_instance.RaiseExceptionEvent(request, error.Value, s_innerExceptionField.GetValue(_Connection) as Exception);
}
}

base.RemoveAt(index);
}
}

Expand All @@ -583,7 +610,7 @@ private HttpHandlerDiagnosticListener() : base(DiagnosticListenerName)

private void RaiseRequestEvent(HttpWebRequest request)
{
if (request.Headers.Get(RequestIdHeaderName) != null)
if (IsRequestInstrumented(request))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does anything bad happen if we don't change this line?

If there was an instrumenter that used traceparent previously they could rely on this code (maybe even unintentionally) to set tracestate, correlationcontext, and send a started event. Now we have surpressed all that behavior it may be breaking their scenario?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@noahfalk You are right, it could be breaking. BUT, check out dotnet/corefx#40777. That just went out with .NET 5 Preview 1 (pretty sure?). That PR fixes/breaks 1 of the 2 events. This PR adds 1 new event and then makes it consistent for all 3. IMO better to have the consistency than 1 working differently? LMK

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If it is consistency just for consistency's sake I'd prioritize the back-compat risk higher. If the lack of consistency results in a specific harm to some customer or tool I'd want to give that greater consideration.

check out dotnet/corefx#40777

I am making an educated guess that adding new events where they were previously missing/absent has a much lower risk of breaking compat than removing functionality does. As far as I could tell this was the only spot where we potentially stop doing work that happened before whereas all the other edits in this PR and in 40777 are adding things. Also I expect it is relatively easy to workaround getting too many events/activities because tools can ignore them whereas working around a missing event is very hard.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd say taking dependency on that behavior was wrong... Let's make it consistent and predictable

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd say taking dependency on that behavior was wrong

Valuing back-compat means I won't second-guess whether dependencies on our current behavior are wise, reasonable, or intentional. I only care how likely it is that the dependencies exist and weigh the harm it would cause customers to have their working app break vs. the value the change brings.

Let's make it consistent and predictable

These aren't the attributes I value much when modifying existing shipping code. If there are specific scenarios that customers are likely to hit and making this change will benefit them then that could be compelling. Otherwise I am quite content sticking with the devil I know : )

{
// this request was instrumented by previous RaiseRequestEvent
return;
Expand All @@ -593,15 +620,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)
{
Expand All @@ -618,14 +637,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)
Expand All @@ -648,18 +664,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 });
Expand All @@ -671,12 +697,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)
Expand Down Expand Up @@ -706,6 +740,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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do we have confidence these fields exist in every past version of HttpClient? (I don't have any specific reason to believe there is an issue, solely making sure we've done due diligence)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@noahfalk Good call. I checked the .NET 4.5.1 reference source, they are present (ndp\fx\src\Net\System\Net_Connection.cs). Happy to check others, but not sure where to find them. Here's where I got 4.5.1: https://referencesource.microsoft.com/download.html

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I confirmed they exist in 4.5 and the library doesn't target anything earlier than 4.5. For releases after 4.5.1 there are more buttons on the reference source page you linked.


s_httpResponseAccessor = CreateFieldGetter<HttpWebRequest, HttpWebResponse>("_HttpResponse", BindingFlags.NonPublic | BindingFlags.Instance);
s_autoRedirectsAccessor = CreateFieldGetter<HttpWebRequest, int>("_AutoRedirects", BindingFlags.NonPublic | BindingFlags.Instance);
Expand All @@ -723,6 +759,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 ||
Expand Down Expand Up @@ -792,13 +830,14 @@ private static Func<object, TField> CreateFieldGetter<TField>(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";
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";
Expand All @@ -807,14 +846,16 @@ private static Func<object, TField> CreateFieldGetter<TField>(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;
private static Type s_connectionGroupType;
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<HttpWebRequest, HttpWebResponse> s_httpResponseAccessor;
private static Func<HttpWebRequest, int> s_autoRedirectsAccessor;
private static Func<HttpWebRequest, object> s_coreResponseAccessor;
Expand Down
Loading