EventSource hierarchical activity ids are missing unless another listener is also listening.

[ghelyar]

I have a custom EventSource, which has Start and Stop events.

If I am collecting on that EventSource in PerfView or in Visual Studio 2017's "Diagnostic Events" window, I see activity IDs in the other viewer on both my Start and Stop events, and on my Start events only in EventFlow, with the Stop events offset by one level.

If I am only listening with EventFlow, as it would be in production, I do not see any hierarchical activity IDs (e.g. "//1/2/3") at all.

I got the same behaviour by using EventListener (with the TPL provider) directly.

Here is the output I see on .net 4.6.2 when using the EventSource input and a custom output that writes the payload serialised as JSON:

Without any other viewer:

{"EventId":1,"EventName":"OuterStart"}
{"EventId":3,"EventName":"InnerStart"}
{"EventId":4,"EventName":"InnerStop"}
{"EventId":2,"EventName":"OuterStop"}

With no code changes, but visual studio -> view -> other windows -> diagnostic events and the event source name added:

{"EventId":1,"EventName":"OuterStart","ActivityId":"//1/2/"}
{"EventId":3,"EventName":"InnerStart","ActivityId":"//1/2/1/","RelatedActivityId":"00000012-0000-0000-0000-0000bf999d59"}
{"EventId":4,"EventName":"InnerStop","ActivityId":"//1/2/"}
{"EventId":2,"EventName":"OuterStop"}

Notes:

• Without another viewer listening to the event source at the same time, activity ID is missing.
• Even when present, the stop events have the wrong activity IDs (when compared to either PerfView or VS' Diagnostic Events window) https://stackoverflow.com/questions/42957473/what-could-be-the-reason-for-my-eventlistener-to-get-empty-activityid-values also shows this The expected Activity IDs and Related Activity IDs (as shown by the other viewers at the same time) respectively would be

  OuterStart: //1/2, null
  InnerStart: //1/2/1, //1/2
  InnerStop: //1/2/1, null
  OuterStop: //1/2, null

• Related activity ID is not converted to an activity path. I can see from EventDataExtensions.cs that ToString() is called rather than GetActivityPathString() for RelatedActivityId

This seems to be a problem with the EventSource input (or EventListener itself) but not the ETW input. With the ETW input, I see the following output:

{"ID":1,"EventName":"Outer/Start","ActivityID":"//1/2/"}
{"ID":3,"EventName":"Inner/Start","ActivityID":"//1/2/1/","RelatedActivityID":"00000012-0000-0000-0000-0000bf999d59"}
{"ID":4,"EventName":"Inner/Stop","ActivityID":"//1/2/1/"}
{"ID":2,"EventName":"Outer/Stop","ActivityID":"//1/2/"}

Of course, EventSource is preferable to ETW if it can be used, and the same problem with RelatedAcivityId not being treated as an activity path also applies to TraceEventExtensions.cs.

Listening on the ETW input also has the same effect on the EventSource input as PerfView and VS Diagnostic Events, but of course it's then double logged with a slightly different payload.

What do I need to do to get hierarchical activity IDs on both my start and stop events with EventFlow and the EventSource input?

[SergeyKanzhelev]

My understanding that this is a limitation of EventSource. Those hierarchical identifiers are available out-proc, but not in-proc.

@vancem are there any plans to enable obtaining the hierarchical identifier from inside the process using EventListener?

[karolz-ms]

Um, not necessarily, I believe this should work, although hierarchical IDs need to be explicitly enabled. I thought we do that in EventSource input already, but there might be bugs.

@ghelyar it would be really helpful if you provided us with a gist reproducing the issue (which would show both your EventSource as well as how you create the EventFlow pipeline).

[ghelyar]

I think the missing activity IDs and bad activity IDs on stop events may be problems with EventListener rather than EventFlow, as I could reproduce them with EventListener directly. When using EventListener directly I had to subscribe to the TPL event source and run the extra listener. With EventFlow I only had to run the extra listener.

Converting related activity IDs to GUID shaped strings rather than to activity paths is something that is caused by EventFlow in both the EventSource and ETW inputs (links to exact lines in my post above), but it can at least be reversed. It just means that a custom output needs to be used and it needs to do something like:

if(payload.ContainsKey("RelatedActivityId") {
  payload["RelatedActivityId"] = ActivityPathDecoder.GetActivityPathString(Guid.Parse((string)payload["RelatedActivityId"]))
}

which is not ideal.

gist here

The output I get with this is:

[1] {"Timestamp":"2017-08-07T16:05:28.5921582+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":1,"EventName":"OuterStart"}}
[1] {"Timestamp":"2017-08-07T16:05:28.6141999+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":3,"EventName":"InnerStart"}}
[1] {"Timestamp":"2017-08-07T16:05:28.6141999+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":4,"EventName":"InnerStop"}}
[1] {"Timestamp":"2017-08-07T16:05:28.6141999+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":2,"EventName":"OuterStop"}}

or, if I start another out of process listener first like VS Diagnostic Events:

[1] {"Timestamp":"2017-08-07T16:13:49.9168935+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":1,"EventName":"OuterStart","ActivityId":"//1/1/"}}
[1] {"Timestamp":"2017-08-07T16:13:49.9399037+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":3,"EventName":"InnerStart","ActivityId":"//1/1/1/","RelatedActivityId":"00000011-0000-0000-0000-0000be999d59"}}
[1] {"Timestamp":"2017-08-07T16:13:49.9399037+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":4,"EventName":"InnerStop","ActivityId":"//1/1/"}}
[1] {"Timestamp":"2017-08-07T16:13:49.9399037+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"EventId":2,"EventName":"OuterStop"}}

With the EventSource input replaced by an ETW input, the output is:

[1] {"Timestamp":"2017-08-07T16:20:56.5408708+00:00","ProviderName":"CustomEventSource","Level":0,"Keywords":72057594037927935,"Payload":{"ID":65534,"EventName":"ManifestData","Format":1,"MajorVersion":1,"MinorVersion":0,"Magic":91,"TotalChunks":1,"ChunkNumber":0}}
[1] {"Timestamp":"2017-08-07T16:20:56.6013823+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"ID":1,"EventName":"Outer/Start","ActivityID":"//1/1/"}}
[1] {"Timestamp":"2017-08-07T16:20:56.6015009+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"ID":3,"EventName":"Inner/Start","ActivityID":"//1/1/1/","RelatedActivityID":"00000011-0000-0000-0000-0000be999d59"}}
[1] {"Timestamp":"2017-08-07T16:20:56.6015722+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"ID":4,"EventName":"Inner/Stop","ActivityID":"//1/1/1/"}}
[1] {"Timestamp":"2017-08-07T16:20:56.6016302+00:00","ProviderName":"CustomEventSource","Level":4,"Keywords":263882790666240,"Payload":{"ID":2,"EventName":"Outer/Stop","ActivityID":"//1/1/"}}

[karolz-ms]

OK, thanks, I can reproduce. Investigating...

[karolz-ms]

So far I found out the following: there is a bug in .NET Framework that prevents turning on activity tracking from managed code. This bug is only fixed in .NET Core 2.0. That is why there is no activity information when only EventFlow is used, and that is why they show up when VS diagnostics viewer, or ETW input, are used (because they turn activity tracking on in a different manner).

The activity paths do seem strange, may be another bug, still investigating. Will let you know what I find.

Just a note: related activity ID will never be encoded as a path GUID, so there is no point to attempt to decode it that way.

[ghelyar]

Thanks for looking into it.

Do you know if it will be fixed in .net framework in the future? .net core is not quite mature enough for us to use at the moment.

Can you point me in the direction of any more information on the different manner in which ETW enables activity tracking? I wouldn't mind pinvoking some unmanaged code if it was possible to enable it that way and the stop events had the correct activity IDs.

related activity ID will never be encoded as a path GUID

I'm not quite sure what you mean by this.

• Related activity ID clearly is an encoded activity path in the example above: "RelatedActivityID":"00000011-0000-0000-0000-0000be999d59" (this is the GUID for //1/1)
• When you write a Start event, it takes the current activity ID and sets it to the related activity ID, then restores it on the corresponding Stop, so anything which is an activity ID, as implied by the name, can also be a related activity ID.
• This relationship allows start/stop trees to be generated (perfview can do this), but it relies on being able to map activity IDs to related activity IDs.
• PerfView shows related activity IDs as activity paths:
• Visual Studio's diagnostic events window shows shows related activity IDs as activity paths:

The only thing I've found which doesn't convert related activity IDs to activity paths (but does convert activity IDs) is EventFlow.

[vancem]

Adding @brianrob

[karolz-ms]

Sorry @ghelyar, my bad, you are right regarding related activity ID being encoded as activity path.

I guess the point that I was trying to make is that if activity paths are set on events correctly, then you do not really need the value of the related activity ID, because it is, by definition, the parent activity. But for consistency we should probably decode them just like PerfView/VS Diagnostics Viewer does; I will make that change.

The reason that activity GUIDs are always converted to strings is to avoid a situation where an event property is sometimes a GUID and sometimes a string. That has been proven problematic in the past.

I am also being told that the truncated activity paths that you see for Stop events are not expected. I have passed that investigation to the Core CLR team (@brianrob and @vancem)

[SergeyKanzhelev]

@karolz-ms would you make the same change (path decoding) in Application Insights EventSource listener, please?

[karolz-ms]

@SergeyKanzhelev yes of course :-)

[karolz-ms]

The related activity ID is now being decoded, starting with the release 1.1.2 of the EventSource input.

Given that all the other problems with the scenario are pretty much external to EventFlow, I am going to close this issue now.

[munik]

Is there any update on whether this will be fixed in the .NET Framework? I can confirm that as of .NET Framework 4.7.1, EventListener still doesn't return activity path-style Activity IDs for captured events.

[karolz-ms]

Sorry I do not know. I suspect there are backward-compat concerns that prevent the enablement of activity tracking from managed code to be fixed in .NET 47/4.8. @brianrob do you have any updates on this?

[vancem]

• @noahfalk @tommcdon

Is there any update on whether this will be fixed in the .NET Framework? I can confirm that as of .NET > Framework 4.7.1, EventListener still doesn't return activity path-style Activity IDs for captured events.

@munik, @karolz-ms - there is not a automatic propagation to the .NET Desktop Framework for fixes made to the .NET Core framework. As a minimum there needs to be a sponsor (someone asking for it), and even then it will take a while). Indeed it is already reasonably late for anything to get into V4.8 (the next release).

If you wish to pursue this we need to determine the fixes you need (ideally the .NET Core bugs that fixed the issue in .NET Core), along with a description of the value/impact. @tommcdon can help you from there.