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

Jump to bottom

Detect broken Activity stack and gracefully end the loop #23

Merged
merged 5 commits into from
Mar 30, 2018
Merged

Detect broken Activity stack and gracefully end the loop #23

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d0d753f
Fix endless loop in case some activity in the stack is stopped in the…
Mar 29, 2018
24ba323
minor fixes
Mar 29, 2018
b0216fa
Add event source events
Mar 29, 2018
7e20f06
Return DS back to 4.4.0
Mar 29, 2018
e0a29e1
fix typos and review severity of event source events
Mar 29, 2018
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
81 changes: 65 additions & 16 deletions src/Microsoft.AspNet.TelemetryCorrelation/ActivityHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ internal static class ActivityHelper
/// </summary>
public const string ActivityKey = "__AspnetActivity__";

private const int MaxActivityStackSize = 128;
private static readonly DiagnosticListener AspNetListener = new DiagnosticListener(AspNetListenerName);

/// <summary>
Expand Down Expand Up @@ -66,14 +67,52 @@ public static Activity RestoreCurrentActivity(Activity root)
return childActivity;
}

/// <summary>
/// Stops the activity and notifies listeners about it.
/// </summary>
/// <param name="activity">Activity to stop.</param>
/// <param name="context">Current HttpContext.</param>
/// <returns>True if activity was found in the stack, false otherwise.</returns>
public static bool StopAspNetActivity(Activity activity, HttpContext context)
{
if (activity != null && Activity.Current != null)
var currentActivity = Activity.Current;
if (activity != null && currentActivity != null)
{
// silently stop all child activities before activity
while (Activity.Current != activity && Activity.Current != null)
int iteration = 0;
while (currentActivity != activity)
Copy link
Contributor

Choose a reason for hiding this comment

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

we may need a similar logic in recent PR with the tags reading in base SDK

Copy link
Author

Choose a reason for hiding this comment

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

in the base SDK we don't walk up the stack of activities to find ours. If current does not match current operation, we just fail. We can do that for sure, I'll create an issue

Copy link
Contributor

Choose a reason for hiding this comment

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

I mean for the recent PR where tags are read from all parents

Copy link
Author

Choose a reason for hiding this comment

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

If you mean this one: microsoft/ApplicationInsights-dotnet#736, it is for initializing/tracking telemetry before Activity is stopped. Basically, it allows customers to use tags themselves with a custom initializer.

For parent tags reading, walking up the stack is not a problem, as Parent for 'broken' Activity is correct, it's just Stop() that never updates Current to Parent.

Copy link
Contributor

Choose a reason for hiding this comment

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

I was confused. I though to fix this one: microsoft/ApplicationInsights-dotnet#562 we will walk up the parents. When we will be implementing this we need to have the same protection there

Copy link
Author

Choose a reason for hiding this comment

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

There is no problem with parent walking, i.e.

var activity = Activity.Current;
while (activity != null) {
  // do something
  activity = activity.Parent;
}

is not affected by this Stop issue.

It might be a hypothetical problem if we'll ever have a cycle in the parents stack.
I'll update the Tags issue and mention it.

{
Activity.Current.Stop();
currentActivity.Stop();
var newCurrentActivity = Activity.Current;

if (newCurrentActivity == null)
{
break;
}

// there could be a case when request or any child activity is stopped
// from the child execution context. In this case, Activity is present in the Current Stack,
// but is finished, i.e. stopping it has no effect on the Current.
if (newCurrentActivity == currentActivity)
{
// We could not reach our 'activity' in the stack and have to report 'lost activity'
// if child activity is broken, we can still stop the root one that we own to clean up
// all resources
AspNetTelemetryCorrelationEventSource.Log.FinishedActivityIsDetected(currentActivity.Id, currentActivity.OperationName);
activity.Stop();
return false;
}

// We also protect from endless loop with the MaxActivityStackSize
// in case it would ever be possible to have cycles in the Activity stack.
if (iteration++ == MaxActivityStackSize)
{
AspNetTelemetryCorrelationEventSource.Log.ActivityStackIsTooDeep(currentActivity.Id, currentActivity.OperationName);
activity.Stop();
return false;
}

currentActivity = newCurrentActivity;
}

// if activity is in the stack, stop it with Stop event
Expand All @@ -89,6 +128,11 @@ public static bool StopAspNetActivity(Activity activity, HttpContext context)
return false;
}

/// <summary>
/// Notifies listeners that activity was ended and lost during execution.
/// </summary>
/// <param name="activity">Activity to notify about.</param>
/// <param name="context">Current HttpContext.</param>
public static void StopLostActivity(Activity activity, HttpContext context)
{
if (activity != null)
Expand All @@ -99,6 +143,11 @@ public static void StopLostActivity(Activity activity, HttpContext context)
}
}

/// <summary>
/// Creates root (first level) activity that describes incoming request.
/// </summary>
/// <param name="context">Current HttpContext.</param>
/// <returns>New root activity.</returns>
public static Activity CreateRootActivity(HttpContext context)
{
if (AspNetListener.IsEnabled() && AspNetListener.IsEnabled(AspNetActivityName))
Expand All @@ -117,6 +166,19 @@ public static Activity CreateRootActivity(HttpContext context)
return null;
}

/// <summary>
/// This should be called after the Activity starts and only for root activity of a request.
/// </summary>
/// <param name="context">Context to save context to.</param>
/// <param name="activity">Activity to save.</param>
internal static void SaveCurrentActivity(HttpContext context, Activity activity)
{
Debug.Assert(context != null);
Debug.Assert(activity != null);

context.Items[ActivityKey] = activity;
}

private static bool StartAspNetActivity(Activity activity)
{
if (AspNetListener.IsEnabled(AspNetActivityName, activity, new { }))
Expand All @@ -136,19 +198,6 @@ private static bool StartAspNetActivity(Activity activity)
return false;
}

/// <summary>
/// This should be called after the Activity starts and only for root activity of a request.
/// </summary>
/// <param name="context">Context to save context to.</param>
/// <param name="activity">Activity to save.</param>
private static void SaveCurrentActivity(HttpContext context, Activity activity)
{
Debug.Assert(context != null);
Debug.Assert(activity != null);

context.Items[ActivityKey] = activity;
}

private static void RemoveCurrentActivity(HttpContext context)
{
Debug.Assert(context != null);
Expand Down
14 changes: 13 additions & 1 deletion src/Microsoft.AspNet.TelemetryCorrelation/AspNetTelemetryCorrelationEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ public void ActivityStopped(string id, bool lost = false)
WriteEvent(3, id, lost);
}

[Event(4, Message = "Failed to parse header '{0}', value: '{1}'", Level = EventLevel.Error)]
[Event(4, Message = "Failed to parse header '{0}', value: '{1}'", Level = EventLevel.Informational)]
public void HeaderParsingError(string headerName, string headerValue)
{
WriteEvent(4, headerName, headerValue);
Expand All @@ -46,6 +46,18 @@ public void ActvityExtractionError(string reason)
{
WriteEvent(5, reason);
}

[Event(6, Message = "Finished Activity is detected on the stack, Id: '{0}', Name: '{1}'", Level = EventLevel.Error)]
public void FinishedActivityIsDetected(string id, string name)
{
WriteEvent(6, id, name);
}

[Event(7, Message = "Activity stack is too deep, Current Id: '{0}', Name: '{1}'", Level = EventLevel.Error)]
Copy link
Contributor

Choose a reason for hiding this comment

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

It may be a good idea to subscribe on these in base SDK so we have them reported as SDK errors.

Copy link
Author

Choose a reason for hiding this comment

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

Agree, will do

public void ActivityStackIsTooDeep(string id, string name)
{
WriteEvent(7, id, name);
}
}
}
#pragma warning restore SA1600 // Elements must be documented
4 changes: 3 additions & 1 deletion src/Microsoft.AspNet.TelemetryCorrelation/Microsoft.AspNet.TelemetryCorrelation.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,9 @@
</ItemGroup>
<ItemGroup>
<None Include="Microsoft.AspNet.TelemetryCorrelation.ruleset" />
<None Include="packages.config" />
<None Include="packages.config">
<SubType>Designer</SubType>
</None>
</ItemGroup>
<ItemGroup>
<Analyzer Include="..\..\packages\StyleCop.Analyzers.1.0.0\analyzers\dotnet\cs\Newtonsoft.Json.dll" />
Expand Down
50 changes: 50 additions & 0 deletions test/Microsoft.AspNet.TelemetryCorrelation.Tests/ActivityHelperTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -126,6 +126,56 @@ public void Can_Stop_Child_Activity_With_All_Children()
Assert.Equal(rootActivity, Activity.Current);
Assert.Null(context.Items[ActivityHelper.ActivityKey]);
}

[Fact]
public async Task Can_Stop_Root_Activity_If_It_Is_Broken()
{
var context = HttpContextHelper.GetFakeHttpContext();
var root = new Activity("root").Start();
ActivityHelper.SaveCurrentActivity(context, root);

new Activity("child").Start();

for (int i = 0; i < 2; i++)
{
await Task.Run(() =>
{
// when we enter this method, Current is 'child' activity
Activity.Current.Stop();
// here Current is 'parent', but only in this execution context
});
}

// when we return back here, in the 'parent' execution context
// Current is still 'child' activity - changes in child context (inside Task.Run)
// do not affect 'parent' context in which Task.Run is called.
// But 'child' Activity is stopped, thus consequent calls to Stop will
// not update Current
Assert.False(ActivityHelper.StopAspNetActivity(root, context));
Assert.NotNull(context.Items[ActivityHelper.ActivityKey]);
Assert.Null(Activity.Current);
}

[Fact]
public void Stop_Root_Activity_With_129_Nesting_Depth()
{
var context = HttpContextHelper.GetFakeHttpContext();
var root = new Activity("root").Start();
ActivityHelper.SaveCurrentActivity(context, root);

for (int i = 0; i < 129; i++)
{
new Activity("child" + i).Start();
}

// we do not allow more than 128 nested activities here
// only to protect from hypothetical cycles in Activity stack
Assert.False(ActivityHelper.StopAspNetActivity(root, context));

Assert.NotNull(context.Items[ActivityHelper.ActivityKey]);
Assert.Null(Activity.Current);
}

#endregion

#region CreateRootActivity tests
Expand Down