ActivityId missing in a newly added HttpTelemetry Stop events.

[ManickaP]

In non-trivial number of cases, the RequestStop event has empty activity id.

9 945 out of 35 452 requests sent during HTTP FunctionalTests were missing activity id.

Other Start/Stop event pairs introduced with the new telemetry are not properly linked with ActivityId as well.

Also easily reproducible with a simple HttpClient scenario:

class Program
{
    static async Task Main(string[] args)
    {
        using var listener = new HttpEventListener();
        using var client = new HttpClient();
        
        await client.GetAsync(@"https://github.com/dotnet/runtime/blob/master/src/libraries/System.Net.Http/src/HttpDiagnosticsGuide.md");
    }
}

internal sealed class HttpEventListener : EventListener
{
    public const EventKeywords TasksFlowActivityIds = (EventKeywords)0x80;
    //public const EventKeywords Debug = (EventKeywords)0x20000;

    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name == "System.Net.Http" ||
            eventSource.Name == "System.Net.Sockets" ||
            eventSource.Name == "System.Net.Security" ||
            eventSource.Name == "System.Net.NameResolution")
        {
            EnableEvents(eventSource, EventLevel.LogAlways);
        }
        else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            EnableEvents(eventSource, EventLevel.LogAlways, TasksFlowActivityIds /*| Debug*/);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        var sb = new StringBuilder().Append($"{eventData.TimeStamp:HH:mm:ss.fffffff}[{eventData.EventName}]{eventData.ActivityId}.{eventData.RelatedActivityId} ");
        for (int i = 0; i < eventData.Payload?.Count; i++)
        {
            if (i > 0)
                sb.Append(", ");
            sb.Append(eventData.PayloadNames?[i]).Append(": ").Append(eventData.Payload[i]);
        }
        Console.WriteLine(sb.ToString());
    }
}

Result (with the change in #41022)

09:34:45.3129327[RequestStart]00000011-0000-0000-0000-0000093f9d59.00000000-0000-0000-0000-000000000000 scheme: https, host: github.com, port: 443, pathAndQuery: /dotnet/runtime/blob/master/src/libraries/System.Net.Http/src/HttpDiagnosticsGuide.md, versionMajor: 1, versionMinor: 1
09:34:45.4344957[ResolutionStart]00001011-0000-0000-0000-0000090f9d59.00000011-0000-0000-0000-0000093f9d59 hostNameOrAddress: github.com
09:34:45.4752982[ResolutionStop]00001011-0000-0000-0000-0000090f9d59.00000000-0000-0000-0000-000000000000 
09:34:45.4848747[ConnectStart]00002011-0000-0000-0000-0000091f9d59.00000011-0000-0000-0000-0000093f9d59 address: InterNetworkV6:28:{1,187,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,255,140,82,118,3,0,0,0,0}
09:34:45.5208470[ConnectStop]00002011-0000-0000-0000-0000091f9d59.00000000-0000-0000-0000-000000000000 
09:34:45.5347626[HandshakeStart]00003011-0000-0000-0000-0000096f9d59.00000011-0000-0000-0000-0000093f9d59 isServer: False, targetHost: github.com
09:34:45.8030641[HandshakeStop]00003011-0000-0000-0000-0000096f9d59.00000000-0000-0000-0000-000000000000 protocol: Tls13
09:34:45.8070942[Http11ConnectionEstablished]00000011-0000-0000-0000-0000093f9d59.00000000-0000-0000-0000-000000000000 
09:34:46.2040073[ResponseHeadersBegin]00000011-0000-0000-0000-0000093f9d59.00000000-0000-0000-0000-000000000000 
09:34:46.3278444[RequestStop]00000011-0000-0000-0000-0000093f9d59.00000000-0000-0000-0000-000000000000

Un-paired Stop events:
- ResolutionStop: ran in continuation: https://github.com/dotnet/runtime/blob/master/src/libraries/System.Net.NameResolution/src/System/Net/Dns.cs#L485
- ConnectStop: ran in SocketsEventArgs: https://github.com/dotnet/runtime/blob/master/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs#L744
- HandshakeStop: ran in continuation: https://github.com/dotnet/runtime/blob/master/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs#L240
They're paired, I misinterpreted the logs. The Stop event doesn't carry parent activity id, only the start one.

What needs to be done to achieve desired statistics:

• Fix Request events Moved HTTP request telemetry to HttpClient.SendAsync #41022
• Fix Resolution events wrongly interpreted logs
• Fix Connect events wrongly interpreted logs
• Fix Handshake events wrongly interpreted logs
• Add events (Start/Stop) for request headers sent
• Add events (Start/Stop) for request body sent
• Add events (Start/Stop) for response headers received
• Add events (Start/Stop) for response body received when we buffer it Moved HTTP request telemetry to HttpClient.SendAsync #41022
• Add events (Start/Stop) to convenience methods using ResponseHeadersRead for the whole method Moved HTTP request telemetry to HttpClient.SendAsync #41022
• Add events (Start/Stop) to convenience methods for the response stream reading (the same pair as in for response body received) Moved HTTP request telemetry to HttpClient.SendAsync #41022
• Document how to add custom Start/Stop events for users using ResponseHeadersRead that want to properly time response body reading (based on our solution for convenience methods)

We can also add or leave existing unpaired telemetry (though it shouldn't be named Start/Stop then) for events that cannot be bound by a single async context. We can link them to the Start/Stop events manually either via remembering ActivityId or using some other custom ID.

cc: @samsp-msft @MihaZupan @karelz

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

[ManickaP]

I might have found the root cause of this problem.
When I fetch an HTTP response without content, the ActivityId is present in the Stop event.

The RequestStop is called only after the response has been read to the end, which happens outside of the async scope started when RequestStart was called.

Details:

RequestStart is called in HttpConnectionPoolManager, several levels down from HttpClient.SendAsync.
RequestStop is called in HttpRequestMessage called when the response content stream has been read: e.g.: ContentLengthReadStream. Which is either called by the user, or in case of response buffering, in HttpClient.FinishSendAsync.

Several options how to solve it:

• track only request part of request / response exchange, i.e. call stop sooner.
  • maybe add separate tracking for response (no idea if it's doable)
• manually handle activity id and pass it to the stop event (no idea if it's doable)
• keep it as it is, pairing won't work
  • manually add custom identifier into the logging so at least something can be used

[noahfalk]

@ManickaP nice investigating 👍
Indeed as you observed, ActivityId is async-local so it flows from parent to child when creating a Task but changes do not flow back from child to parent when an await completes.

I'm not knowledgeable about the networking code, but is there an option to call Start() sooner so that it runs in the same Task where Stop() will eventually be called? Other more customized solutions may also be possible, but I've never attempted to author one and my suspicion is it would get messy.

[ManickaP]

is there an option to call Start() sooner so that it runs in the same Task where Stop() will eventually be called?

We could, theoretically, run it from HttpClient.SendAsync, but that would only help us with buffered responses. In the other case, the request gets finished after the user either disposes it or reads the response stream till the end and we have no control over when and where this happens.

Is there a way to manually retrieve and later attach the ActivityId to the stop event?

[MihaZupan]

As @ManickaP said, we could only do that for buffered responses. For unbuffered ones, we hand out the response that the user can interact with that will eventaully trigger a Stop event.

If I'm understanding this correctly, we can't flow the ActivityID up to the parent?
In that case, is the HttpClient design (handing out the response to the caller to process) incompatible with a Start/Stop activity tracking the entire processing lifetime?

If we give up on tracking the response portion, we would cut into the value of the activity. At that point we would be telling users to log their own Start/Stop activity enclosing the processing of a request.

Alternatively, would introducing a "SendAndProcessWithTelemetryAsync" method that takes a callback make any sense? In that can we could ensure that everything happens in the same scope.

Something along the lines of (just a rough idea):

// On HttpClient
Task<HttpResponseMessage> SendAndProcessWithTelemetryAsync(HttpRequestMessage request, HttpCompletionOption completionOption, Func<HttpResponseMessage, Task> responseCallback, CancellationToken cancellationToken)
{
    TelemetryStart();
    try
    {
        HttpResponseMessage response = await this.SendAsync(request, completionOption, cancellationToken);
        await responseCallback(response);
        TelemetryStop();
        return response;
    }
    catch
    {
        TelemetryAbort(); // Which also logs Stop
        throw;
    }
}

[ManickaP]

Alternatively, would introducing a "SendAndProcessWithTelemetryAsync" method that takes a callback make any sense? In that can we could ensure that everything happens in the same scope.

That would measure/trace different things depending of HttpCompletionOptions, for buffered it'd include reading the response, for read-headers it wouldn't.
It's similar the first solution I suggested in here: #40776 (comment).

[MihaZupan]

for read-headers it wouldn't.

The idea is that it would be captured in the user-provided callback.

Essentially if a user had code like

Task DoSomethingWithResponseAsync(HttpResponseMessage response) {}

var response = await client.SendAsync(request, completionOption);
await DoSomethingWithResponseAsync(response);

it would turn into

await client.SendAndProcessWithTelemetryAsync(request, completionOption, DoSomethingWithResponseAsync);

That way the Telemetry Start/Stop would be in the enclosing scope of the response processing.