Skip to content
This repository has been archived by the owner on Jul 5, 2020. It is now read-only.

Track dependency instrumented with HttpDesktop DiagnosticSource in Response event (#509) #516

Merged
merged 11 commits into from
May 4, 2017

Conversation

lmolkova
Copy link
Member

@lmolkova lmolkova commented Apr 28, 2017

See #509 for the details.

Please note:

  1. Before this fix, all dependencies are reported, but none of the dependencies instrumented with DiagnosticSource have proper Target with appId.

  2. After this fix

  • dependency has proper target if AppId was returned in response header
  • for requests with redirects, only first call is tracked (so the duration and status are wrong). This we should fix in DiagnosticSource. (Update fixed and merged)
  • some dependency calls may be missed if they are done with WebRequest.GetResponse() AND response is not disposed. This is fundamental flaw in the reflection hook and there is no know solution for this issue.
    E.g.
            HttpWebRequest request = WebRequest.CreateHttp("http://localhost:3000");
            HttpWebResponse response = (HttpWebResponse)request.GetResponse();

Will never be tracked... Application that does not dispose WebRequests may run short on the available connections, so in most cases uses will dispose them.

            HttpWebRequest request = WebRequest.CreateHttp("http://localhost:3000");
            using( HttpWebResponse response = (HttpWebResponse)request.GetResponse())
            {
            }

Will be tracked.
This problem does not affect requests done with HttpClient as responses are disposed.


Considering that some dependencies may not be collected and it does not look fixable, please decide whether this fix should be taken at all.
Otherwise, just keep current implementation (and sacrifice AppId for all dependencies).

DependencyTelemetry remoteDependencyTelemetryActual, Uri url, string kind, bool? success, double valueMin, string statusCode)
{
Assert.AreEqual("GET " + url.AbsolutePath, remoteDependencyTelemetryActual.Name, true, "Resource name in the sent telemetry is wrong");
string expectedVersion = SdkVersionHelper.GetExpectedSdkVersion(typeof(DependencyTrackingTelemetryModule), prefix: "rddfd:");
ValidateTelemetryPacket(remoteDependencyTelemetryActual, url, kind, success, valueMin, statusCode, expectedVersion);
}
}*/
Copy link
Member

Choose a reason for hiding this comment

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

Just delete unneeded code.

Copy link
Member Author

Choose a reason for hiding this comment

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

nice catch!
forgot to remove it

internal ObjectInstanceBasedOperationHolder TelemetryTable;

internal DesktopDiagnosticSourceHttpProcessing(TelemetryConfiguration configuration, ObjectInstanceBasedOperationHolder telemetryTupleHolder, bool setCorrelationHeaders, ICollection<string> correlationDomainExclusionList, string appIdEndpoint)
: base(configuration, SdkVersionUtils.GetSdkVersion("rdd" + RddSource.FrameworkAndDiagnostic + ":"), null, setCorrelationHeaders, correlationDomainExclusionList, appIdEndpoint)
Copy link
Member

Choose a reason for hiding this comment

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

Please check with Sergey if "rdd" should be some other prefix code for uniqueness or not.

Copy link
Member Author

Choose a reason for hiding this comment

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

it was already there (RddSource.FrameworkAndDiagnostic) for this source

Copy link
Contributor

Choose a reason for hiding this comment

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

From this PR, it looks like DiagnosticSource and Framework cannot be active at the same time. So RddSource.FrameworkAndDiagnostic does not make sense here as it was originally intended to tell us dependency was collected by both Framework and Diagnostic source.

Copy link
Member

@dnduffy dnduffy left a comment

Choose a reason for hiding this comment

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

Minor changes/questions.

@lmolkova
Copy link
Member Author

Dan Taylor suggestion is to have a flag that would let users choose what they want to sacrifice :)

using (var reader = new StreamReader(response.GetResponseStream()))
{
reader.ReadToEnd();
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Please retain the test for 'GetResponse() but no subsequent stream read' to test that we wont collect dependencies in that case, and having a test with comments will be easier for future reference.

Copy link
Member Author

Choose a reason for hiding this comment

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

done

[TestMethod]
public void RddTestHttpProcessingFrameworkUpdateTelemetryName()
{
var stopwatch = Stopwatch.StartNew();
Copy link
Contributor

Choose a reason for hiding this comment

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

start stopwatch right before this line 'this.httpProcessingFramework.OnRequestSend(request); Don't want to include the time taken (its too small but still!) for WebRequest.Create.

Copy link
Contributor

Choose a reason for hiding this comment

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

same for all other tests in this class.

@cijothomas
Copy link
Contributor

@dnduffy How important is to get this 2.4.0-beta2 for you to refer in aspnet core? This change is non-trivial, and dont want to include this in beta2 without routine manual tests. Can this wait for 2.4 stable release ?

@lmolkova - Will need to review this in detail+ check functional tests before merging this in.

@lmolkova
Copy link
Member Author

@cijothomas This is for Web SDK, it is quite important for the //build scenarios and stable 2.4.0.

@lmolkova
Copy link
Member Author

lmolkova commented Apr 28, 2017

Update on the issue with not-tracked calls: they will be tracked if the response is closed/disposed properly.

            HttpWebRequest request = WebRequest.CreateHttp("http://localhost:3000");
            using (HttpWebResponse response = (HttpWebResponse)request.GetResponse())
            {
                Console.WriteLine(response.StatusCode);
            }

If app does not dispose WebRequests properly, it could experience a lot of other issues: e.g. reach connection limit.

So I do not consider this is a critical problem anymore even for WebRequests

@lmolkova
Copy link
Member Author

lmolkova commented May 1, 2017

Hey guys, please merge it to develop if possible.
@cijothomas @SergeyKanzhelev

this.sendItems = new List<ITelemetry>();
this.configuration.TelemetryChannel = new StubTelemetryChannel { OnSend = item => this.sendItems.Add(item) };
this.configuration.InstrumentationKey = Guid.NewGuid().ToString();
this.httpProcessingFramework = new DesktopDiagnosticSourceHttpProcessing(this.configuration, new ObjectInstanceBasedOperationHolder(), /*setCorrelationHeaders*/ true, new List<string>(), RandomAppIdEndpoint);
Copy link
Contributor

Choose a reason for hiding this comment

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

httpProcessingFramework - this name is misleading. Please change to reflect the new class name.

Copy link
Contributor

Choose a reason for hiding this comment

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

This is not changed. DesktopDiagnosticSourceHttpProcessingTests is not testing HttpProcessingFramework, but the variable name is telling otherwise. (its difficult to read code with consuing names :( )

Copy link
Contributor

@cijothomas cijothomas left a comment

Choose a reason for hiding this comment

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

Some comments left. Most importantly - can you add/modify Functional tests for the changes? There are a bunch of Functional tests already for dependency collector , please make use of that to validate things end to end.

@cijothomas
Copy link
Contributor

need to discuss about the version prefix. RddSource.FrameworkAndDiagnostic does not seem logical here, rddd maybe okay, but DependencyCollector in Core already uses that, so we need to distinguish that as well.

@@ -221,9 +221,23 @@ protected virtual void Dispose(bool disposing)
/// </summary>
private void InitializeForFrameworkEventSource()
{
#if NET45
Copy link
Contributor

@nizarq nizarq May 2, 2017

Choose a reason for hiding this comment

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

What is the difference between #if NET 45 here and #if !NET40 below. Are we dealing with .net framework < 40?

Copy link
Member Author

Choose a reason for hiding this comment

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

you are right, there is no difference

@lmolkova
Copy link
Member Author

lmolkova commented May 2, 2017

need to discuss about the version prefix. RddSource.FrameworkAndDiagnostic does not seem logical here, rddd maybe okay, but DependencyCollector in Core already uses that, so we need to distinguish that as well.

Core and Desktop will never be active at the same time, but it could be useful to distinguish them anyway. What about 'rdddd' (for rdd desktop diagnostics)? However it seems too similar to 'rddd' used in core.
Please advise what prefix is appropriate. I'm fine with anything.

@lmolkova
Copy link
Member Author

lmolkova commented May 2, 2017

Some comments left. Most importantly - can you add/modify Functional tests for the changes? There are a bunch of Functional tests already for dependency collector , please make use of that to validate things end to end.

There are several difficult aspects of adding/changing functional tests

  1. There is no NET46 app and this instrumentation only works for NET46.
  2. In order to test it end-to-end, we need 2 apps: 1st app that tracks dependency, second app that responds with Request-Context headers.

I would prefer another solution described in #494, so we can have local mocked server and track dependencies done to it. It requires a bit of investment to set up localhost. There are other questions where those tests should live: in unit-tests projects or in functional tests. I would argue to keep them as unit tests.
Anyway, I agree that there should be e2e tests, I agree to add them, however I would take it separately as additional PR, which I can do not earlier than a week from now. For now, end-to-end scenarios for these changes were tested manually.

/// </summary>
internal sealed class DesktopDiagnosticSourceHttpProcessing : HttpProcessing
{
internal ObjectInstanceBasedOperationHolder TelemetryTable;
Copy link
Contributor

Choose a reason for hiding this comment

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

Why make this internal? For tests? Should we make this a private field and expose an internal property instead? It's best practice to have fields private only - properties give more fine grained control on exposing what you want to expose to the outside world - for example may be you only want to give get permissions not set.

Copy link
Member Author

Choose a reason for hiding this comment

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

copy/paste issue

/// Validates that OnRequestSend and OnResponseReceive sends valid telemetry.
/// </summary>
[TestMethod]
public void RddTestHttpProcessingFrameworkUpdateTelemetryName()
Copy link
Contributor

Choose a reason for hiding this comment

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

can you modify all the test names to reflect what they are testing? HttpProcessing vs DesktopDiagnosticsSourceHttpProcessing?

@lmolkova
Copy link
Member Author

lmolkova commented May 2, 2017

Update: redirect issue is fixed in DiagnosticSource

@lmolkova lmolkova force-pushed the lmolkova/FixHttpDesktopSource branch from b237375 to 84bd166 Compare May 2, 2017 20:39
@@ -221,9 +221,21 @@ protected virtual void Dispose(bool disposing)
/// </summary>
private void InitializeForFrameworkEventSource()
Copy link
Contributor

Choose a reason for hiding this comment

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

This name does not hold true anymore as we are not only initializing frameworkeventsource but initializing DiagnosticSource as well.

/// <summary>
/// Concrete class with all processing logic to generate RDD data from the callbacks received from HttpDesktopDiagnosticSourceListener.
/// </summary>
internal sealed class DesktopDiagnosticSourceHttpProcessing : HttpProcessing
Copy link
Contributor

Choose a reason for hiding this comment

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

Won't this receive callbacks for failure cases? I only see logic to handle successfull dependencies.. (FrameworkEventSource, profiler had logic for failed calls)

Copy link
Member Author

Choose a reason for hiding this comment

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

Could you please show me where FrameworkEventSource reports failure cases?
I don't see it here here

And in case of HTTP failure means exception because of e.g. DNS or network issue or cancellation.

@@ -53,7 +53,7 @@ public void OnNext(KeyValuePair<string, object> value)
case "System.Net.Http.Request":
{
var request = (HttpWebRequest)this.requestFetcherRequestEvent.Fetch(value.Value);
Copy link
Contributor

Choose a reason for hiding this comment

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

We need to add DependencyCollectorEventSource.Log.Callback received type of logging here.

@@ -249,8 +249,7 @@ internal object OnBegin(object thisObj, bool skipIfNotNew)
/// <param name="exception">The exception object if any.</param>
/// <param name="thisObj">This object.</param>
/// <param name="returnValue">Return value of the function if any.</param>
/// <param name="endTracking">Whether this method should end the tracking or not.</param>
internal void OnEnd(object exception, object thisObj, object returnValue, bool endTracking)
internal void OnEnd(object exception, object thisObj, object returnValue)
Copy link
Contributor

Choose a reason for hiding this comment

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

HttpProcessing class should not log about callbacks. Do that in the corresponding listeners.

Copy link
Member Author

Choose a reason for hiding this comment

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

Callbacks were not introduced in this PR, moving them goes far beyond this pull request,. This PR a critical issue fix and I doubt we should do more refactoring here

Copy link
Member Author

Choose a reason for hiding this comment

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

I added callback logs into the listener and created an issue to consistently change profiler/httpprocessing logs #537

FrameworkHttpProcessing frameworkHttpProcessing = new FrameworkHttpProcessing(this.telemetryConfiguration, DependencyTableStore.Instance.WebRequestCacheHolder, this.SetComponentCorrelationHttpHeaders, this.ExcludeComponentCorrelationHttpHeadersOnDomains, this.EffectiveProfileQueryEndpoint);
this.httpDesktopDiagnosticSourceListener = new HttpDesktopDiagnosticSourceListener(frameworkHttpProcessing);
#if NET45
DesktopDiagnosticSourceHttpProcessing desktopHttpProcessing = new DesktopDiagnosticSourceHttpProcessing(
Copy link
Contributor

Choose a reason for hiding this comment

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

we are now enabling both diagnostic source and framework event source. where is the logic to prevent double collection or only one will be active at a time?

Copy link
Member Author

Choose a reason for hiding this comment

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

it's here

In runtime, we do not know what happens first: initialization of Http Desktop DiagnosticSource or initialization of the DependencyTrackingTelemetryModule, so we keep listening to both, but ignoring the EventSource if DiagnosticSource is active.

@lmolkova lmolkova force-pushed the lmolkova/FixHttpDesktopSource branch from e29dc2a to 4f7d151 Compare May 3, 2017 19:05
Copy link
Contributor

@cijothomas cijothomas left a comment

Choose a reason for hiding this comment

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

Please check all the comments. There are lot.

@@ -47,6 +47,11 @@ public class DependencyTrackingTelemetryModule : ITelemetryModule, IDisposable
public bool DisableRuntimeInstrumentation { get; set; }

/// <summary>
/// Gets or sets a value indicating whether to disable runtime instrumentation.
Copy link
Contributor

Choose a reason for hiding this comment

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

minor: incorrect comment.

this.ExcludeComponentCorrelationHttpHeadersOnDomains,
this.EffectiveProfileQueryEndpoint);
this.httpDesktopDiagnosticSourceListener = new HttpDesktopDiagnosticSourceListener(desktopHttpProcessing);
}
Copy link
Contributor

Choose a reason for hiding this comment

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

please add a log here saying DesktopDiagnosticSource was not enabled as it was not enabled in config. Helps in debugging customer issues later.

Copy link
Member Author

Choose a reason for hiding this comment

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

Let's add log that is WAS actually activated.

using System.Net;

/// <summary>
/// Diagnostic listener implementation that listens for Http DiagnosticSource to see all outgoing HTTP dependency requests.
/// </summary>
internal class HttpDesktopDiagnosticSourceListener : IObserver<KeyValuePair<string, object>>, IDisposable
{
private readonly FrameworkHttpProcessing httpProcessingFramework;
private readonly DesktopDiagnosticSourceHttpProcessing httpDesktopProcessingFramework;
Copy link
Contributor

Choose a reason for hiding this comment

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

minor - rename variable to reflect the class name. (Framework at the end will be confusing_)

if (DependencyTableStore.Instance.IsDesktopHttpDiagnosticSourceActivated)
{
// request is handled by Desktop DiagnosticSource Listener
DependencyCollectorEventSource.Log.TrackingAnExistingTelemetryItemVerbose();
Copy link
Contributor

Choose a reason for hiding this comment

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

please use a different log message here. TrackingAnExistingTelemetryItemVerbose() is used for a different purpose (it existed before diagnostic source). Log something like "I am not tracking this, as DesktopDiagnosticSource is already enabled"

Copy link
Member Author

Choose a reason for hiding this comment

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

I've already done that in the next PR #538, there was a special event added there

@@ -48,6 +48,7 @@ public void OnNext(DiagnosticListener value)
if (value.Name == "System.Net.Http.Desktop")
{
this.sourceSubscription = value.Subscribe(this.parent, (Predicate<string>)null);
DependencyTableStore.Instance.IsDesktopHttpDiagnosticSourceActivated = true;
Copy link
Contributor

Choose a reason for hiding this comment

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

Does it need to set this back to false on Dispose?

DependencyCollectorEventSource.Log.ProfilerFailedToAttachError(exp.ToInvariantString());
}
}
else
{
// if config is set to disable runtime instrumentation then default to framework event source
this.InitializeForFrameworkEventSource();
this.InitializeForDiagnosticAndFrameworkEventSource();
DependencyCollectorEventSource.Log.RemoteDependencyModuleVerbose("Runtime instrumentation is set to disabled. Initialize with framework event source instead.");
}
}
else
{
// if profiler is not attached then default to framework event source
Copy link
Contributor

Choose a reason for hiding this comment

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

minor - change comment to indicate eventsouce and/or diagnostic listene.

@@ -165,7 +165,7 @@ internal static void AddTupleForWebDependencies(WebRequest webRequest, Dependenc

Tuple<DependencyTelemetry, bool> telemetryTuple = null;

if (DependencyTableStore.Instance.IsProfilerActivated || PretendProfilerIsAttached)
if (DependencyTableStore.Instance.IsDesktopHttpDiagnosticSourceActivated || DependencyTableStore.Instance.IsProfilerActivated || PretendProfilerIsAttached)
{
Copy link
Contributor

Choose a reason for hiding this comment

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

This does not look right. This means that, even when Profiler is not installed, tuple will be looked up in SQLRequestConditionalHolder - this is incorrect, as without Profiler SQL Dependencies should be stored in SqlRequestCacheHolder.

(More concerning here is - did any functional tests for sql fail? if not there is a test gap)

Copy link
Member Author

Choose a reason for hiding this comment

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

nothing has failed. may be there is a gap

@@ -198,7 +198,7 @@ internal static void AddTupleForSqlDependencies(SqlCommand sqlRequest, Dependenc
}

var telemetryTuple = new Tuple<DependencyTelemetry, bool>(telemetry, isCustomCreated);
Copy link
Contributor

Choose a reason for hiding this comment

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

same comment as above related to SQL without profiler.

Copy link
Member Author

Choose a reason for hiding this comment

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

removed this check for SQL deps, IsDesktopHttpDiagnosticSourceActivated is only for http

@@ -48,6 +48,7 @@ public void OnNext(DiagnosticListener value)
if (value.Name == "System.Net.Http.Desktop")
{
this.sourceSubscription = value.Subscribe(this.parent, (Predicate<string>)null);
DependencyTableStore.Instance.IsDesktopHttpDiagnosticSourceActivated = true;
Copy link
Contributor

Choose a reason for hiding this comment

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

We are counting on HttpDesktopDiagnosticSourceSubscriber OnNext() to set IsDesktopHttpDiagnosticSourceActivated = true. We definitely need unit test to check this.

Also, is there a guarantee that OnNext will be called before any callbacks to Framework event source?? If not, the IsDesktopHttpDiagnosticSourceActivated will be False, and FrameworkEventSource will start collecting dependencies, which might be later collected by DiagnosticSource. (this may be artificial scenario, but i'd like to know if thats even possible)

Copy link
Member Author

Choose a reason for hiding this comment

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

Added checks in DependencyTrackingTelemetryModuleTestNet46.

There is no guarantee that subscription will happen before module initialization. It must happen before the first HTTP outgoing call or will never happen at all.
So if there is a HTTP call, in EventSource we will know for sure if diag source is activated or not

var request = (HttpWebRequest)this.requestFetcherRequestEvent.Fetch(value.Value);
this.httpProcessingFramework.OnRequestSend(request);
DependencyCollectorEventSource.Log.BeginCallbackCalled(request.GetHashCode(), value.Key);
Copy link
Contributor

Choose a reason for hiding this comment

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

Please use a different log message. I understand there is a task opened for fixing the calls backs, but having a new callback log message for 3-4 switch cases in DiagnosticSourceListener should be very easy fix.

Copy link
Member Author

Choose a reason for hiding this comment

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

Why it is important? I pass name of the callback in the parameter

Copy link
Contributor

Choose a reason for hiding this comment

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

ok callback name should be sufficient for now.

@lmolkova lmolkova force-pushed the lmolkova/FixHttpDesktopSource branch from db87b9b to e973cdd Compare May 4, 2017 18:35
@cijothomas cijothomas merged commit f6a6f6f into develop May 4, 2017
@lmolkova lmolkova deleted the lmolkova/FixHttpDesktopSource branch November 8, 2017 18:56
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants