Runtime: Disposing of Activity updates Activity.Current before the end event, which different to DiagnosticSource.EndActivity

[cg110]

Description

While looking at updating some code to use ActivitySource rather than DiagnosticSource, I noticed that the behavior has changed around ending an activity.

With DiagnosticSource.EndActivity:
https://github.com/dotnet/runtime/blob/master/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/DiagnosticSourceActivity.cs#L44

Activity.Current is updated after the event is fired.

With the new ActivitySource based Activity, when Activity is disposed Current is updated before the end event occurs, as dispose calls Stop:
https://github.com/dotnet/runtime/blob/master/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs#L579

Is this an expected change in behavior, as it seems inconsistent as Starting an activity sets current and then fires the start event.

I'd expect symmetry between start/stop, and matching the previous DiagnosticSource behavior.

Configuration

.net framework 4.8
System.Diagnostics.DiagnosticSource nuget: 5.0.0-preview.6.20305.6

Regression?

No, new functionality in 5.0

Other information

I believe this is an api issue, I'd like clarity on when Activity.Current is set, as we have logging code decorator that looks at ambient state using Activity.Current. This picks up Activity info for the Start Event, however, for the End Event it ends up looking at the parent/null, which means the decorator may override properties with Activity.Current (which is the parent), rather than the activity ending.

[msftbot[bot]]

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
Notify danmosemsft if you want to be subscribed.

[tarekgh]

@cg110 thanks for reporting the issue. Usually Activity.Current will have the same instance of the Activity object we'll stop which will be sent as the event parameter.So, I guess the current behavior looks better as when you receive the event, you'll have the activity object we are stopping and also you'll have the updated Activity.Current too. But, if this can cause any behavior confusion, I wouldn't mind to change it.

@noahfalk what do you think?

[tarekgh]

@cijothomas does OT assume anything about the order of the operations here?

[cg110]

The problem is more that in our logging framework, we've decorators that add properties to messages, but they don't have access to the activity, they just see a Trace/Log message go through, and attach properties, we currently have an AsyncLocal with a transaction Id, and want to move to trace context.

Would be interesting to see what OT expects. It's just a bit odd at the end of an activity that the last end activity is traced without an Activity.Current (eg after handling a request)

[cg110]

Perhaps this example better explains, the tracing pre-fixes messages with the Trace context:

[TC:00-090a2ae69d9d604b9588bfe4c5fc7deb-c01526e343e3fa46-00]WCFCall: activity started, from ParentTraceId: NoParentId
[TC:00-090a2ae69d9d604b9588bfe4c5fc7deb-c01526e343e3fa46-00]SDK >>> GetSdkDetails
[TC:00-090a2ae69d9d604b9588bfe4c5fc7deb-c01526e343e3fa46-00]SDK <<< GetSdkDetails (guid=a3b3bd2b-bf8f-462f-bd19-ce83e27d5e89, majorVersion=2)
WCFCall: activity ended, returning to ParentTraceId: NoParentId

Note that the activity end is missing the TC as activity.current isn't set. We do have it in separate properties.

[noahfalk]

Thanks for the report @cg110 👍

I'd suggest that we match the ordering used by DiagnosticSource - stop event comes before Activity.Current changes. In addition to @cg110's scenario there is probably another one where someone using an ActivityListener wants to emulate the DiagnosticSource events for back-compat. If an ActivityListener.Stop() call was implemented to send DiagnosticSource.Write(activityName + ".Stop") it would be very nice if DiagnosticListeners got that event before Activity.Current was updated, matching previous behavior.

For any code running during the callback that wants to know what the new Activity.Current will be after the callback, it can always evaluate Activity.Parent to find out.

[tarekgh]

Sounds good. I'll track fixing this soon then.

[cijothomas]

Agree.

[tarekgh]

Fixed through the linked PR