[Instrumentation.AspNet] Fix activity being closed before processing completes

[qhris]

Fixes #1138.

Findings

This PR implements the fix suggested by @jdaigle.

I have tested this on an a .NET Framework 4.8 ASP MVC application I've been maintaining.

I ran into this issue trying to modify the span name to be prefixed by the http method as recommended by the spec. The problem I ran into was the HttpInListener overriding whatever changes the processor made to the span name.

It also seems odd to me that the activity is closed and then updated (through HttpInListener.OnStopActivity). I think there is a race condition with exporters here. I was able to trigger this by setting a breakpoint before onRequestStoppedCallback is called; sometimes the exported span would have the pre-callback display name and sometimes it would have the post-callback display name. This is due to the exporters being processors, and processors are triggered on stopping the activity (?). This of course depends on you're using the simple exporter or a batched one.

This is how I think it works (pre-patch):

• aspNetActivity.Stop() is called.
• Processors run (including exporters)
• HttpInListener.OnStopActivity is called (through onRequestStoppedCallback.

I'm still pretty new to OTEL in dotnet, so I might be missing something here, but this seems like a problem to me.

Questions

• Should the content.Items[ContextKey] = null be moved as well, as the context is cleared out now before asnNetActivity.Stop() is called?

Changes

This changes the point at which the activity is stopped to after the onRequestStoppedCallback function is called.

For significant contributions please make sure you have completed the following items:

• Appropriate CHANGELOG.md updated for non-trivial changes
• Design discussion issue #
• Changes in public API reviewed

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: qhris / name: Christoffer Hjalmarsson (488d2ac, 9717e8a, 10e949b)
• ✅ login: cijothomas / name: Cijo Thomas (1a72bde, d721019)

[Kielek]

@qhris, please sign CLA, it is hard requirement to proceed with PR.

Please let us know if you have any issue with the procedure.

[qhris]

@Kielek I had missed the CLA requirement as I submitted the PR. I have no idea how that works so I'll look it over tomorrow since I wasn't prepared having to sign something with my physical address...

In regards to the changes:

Something that struck me is that this will be a breaking change as it changes the order of the processor's OnEnd and AspNetInstrumentationOptions.Enrich delegate. Not sure if the current ordering is on purpose or not.

[qhris]

Did some additional testing this morning comparing the flow to a .NET 7 application.

I used OpenTelemetry.Instrumentation.AspNetCore 1.5.1-beta.1

In the .NET 7 application we have the following flow:

1. Incoming http request.
2. Activity is started.
3. Processors run their OnStart.
4. EnrichWithHttpRequest from HttpInListener is called.
5. Request processing (middlewares/controllers).
6. EnrichWithHttpResponse from HttpInListener is called.
7. Processors run their OnEnd.

The .NET Framework application (pre-patch) has the following behavior:

1. Incoming http request.
2. Activity is started.
3. Processors run their OnStart.
4. Enrich with OnStartActivity is called.
5. Request processing (middlewares/controllers).
6. Processors run their OnEnd
7. Enrich with OnStopActivity is called.

This PR would bring the implementations in line between .NET and .NET Framework by swapping items 6 and 7 for .NET Framework.

[cijothomas]

Did some additional testing this morning comparing the flow to a .NET 7 application.

I used OpenTelemetry.Instrumentation.AspNetCore 1.5.1-beta.1

In the .NET 7 application we have the following flow:

1. Incoming http request.
2. Activity is started.
3. Processors run their OnStart.
4. EnrichWithHttpRequest from HttpInListener is called.
5. Request processing (middlewares/controllers).
6. EnrichWithHttpResponse from HttpInListener is called.
7. Processors run their OnEnd.

The .NET Framework application (pre-patch) has the following behavior:

1. Incoming http request.
2. Activity is started.
3. Processors run their OnStart.
4. Enrich with OnStartActivity is called.
5. Request processing (middlewares/controllers).
6. Processors run their OnEnd
7. Enrich with OnStopActivity is called.

This PR would bring the implementations in line between .NET and .NET Framework by swapping items 6 and 7 for .NET Framework.

The ASP.NET Core behavior is correct and this fix for asp.net is correct! Thanks.

[codecov]

Codecov Report

Merging #1388 (10e949b) into main (71655ce) will increase coverage by 6.15%.
Report is 23 commits behind head on main.
The diff coverage is 44.44%.

@@            Coverage Diff             @@
##             main    #1388      +/-   ##
==========================================
+ Coverage   73.91%   80.06%   +6.15%     
==========================================
  Files         267      160     -107     
  Lines        9615     4450    -5165     
==========================================
- Hits         7107     3563    -3544     
+ Misses       2508      887    -1621     

Flag	Coverage Δ
unittests-Instrumentation.AspNet	70.90% <100.00%> (?)
unittests-Solution	80.67% <41.17%> (?)

Flags with carried forward coverage won't be shown. Click here to find out more.

Files	Coverage Δ
...ation.AspNet.TelemetryHttpModule/ActivityHelper.cs	85.24% <100.00%> (ø)
...searchClient/ElasticsearchClientInstrumentation.cs	100.00% <100.00%> (ø)
...ityFrameworkCore/EntityFrameworkInstrumentation.cs	100.00% <100.00%> (ø)
...ation/EntityFrameworkInstrumentationEventSource.cs	12.00% <100.00%> (ø)
...Instrumentation.Quartz/QuartzJobInstrumentation.cs	83.33% <100.00%> (+1.51%)	⬆️
...ry.ResourceDetectors.AWS/AWSEBSResourceDetector.cs	92.30% <ø> (+1.00%)	⬆️
...ntation/ElasticsearchInstrumentationEventSource.cs	7.69% <16.66%> (-4.81%)	⬇️
...Implementation/QuartzInstrumentationEventSource.cs	33.33% <0.00%> (-16.67%)	⬇️

... and 115 files with indirect coverage changes

[cijothomas]

LGTM with a changelog entry!
Thanks for your contribution!

[utpilla]

You can remove this line. These two packages are always released together.

[utpilla]

@qhris Thanks for fixing the issue.

You can use the 1.6.0-beta.1 version of the instrumentation library which has this fix in it: https://github.com/open-telemetry/opentelemetry-dotnet-contrib/releases/tag/Instrumentation.AspNet-1.6.0-beta.1

[vishweshbankwar]

@qhris This change has a side effect of broken metrics instrumentation.

Now that the activity is stopped after the onStopCallBack is fired, the activity.Duration would always result in 0. In order to fix this, you would need to set the duration of activity before the end callback like below:

if (aspNetActivity.Duration == TimeSpan.Zero)
{
    aspNetActivity.SetEndTime(DateTime.UtcNow);
}

[qhris]

@vishweshbankwar thanks for letting me know, I'll take a look to reproduce and I'll submit a fix for it.
I guess this is another downside of having the metrics being tied to traces...