Orleans semantic logging and related ideas on general interceptor design

[veikkoeeva]

Tagging @jdom and @ReubenBond as they've discussed this in Gitter.

I was learning myself about the new .NET Core tracing and logging infrastructure. This has been discussed in Gitter, but to my knowledge there isn't an open issue that would record the issues in GitHub.

Why:

1. It provides and ambient context (always existing) to record arbitrary interactions on all platforms.
2. It plugs into tooling automatically. I believe AppInsight, and other such tooling, can automatically highlight .NET tracing data.
3. The design allows adding data providers hierarchically, i.e. user defined hierarchies to enrich framework ones, and mechanisms to communicate in distributed fashion (e.g. Baggage). The docs in .md files.

It looks to me this allows building logging and tracing so that Orleans core and even the plugins, can be the root of activities where other components can then add new leaf levels and whatever is deemed OK (such as timing data). This can be the usual variety if logging, but also performance relatated timings. This way also adds a way for uniform naming across the whole .NET ecosystem.

It looks to me this could be done incrementally at least in the non-core parts, like ADO.NET libraries, so that new tracing information is just created if parent activity is null and then when Orleans core adds parent, or root, activities, the providers add tracing information as leaf data (see the following code snippet). I'm unsure if this requires changes to the core besides adding another system for logging and tracing and if so, how much.

A point I noticed about interceptors. It appears this method also allows one to build ambient interceptors. One example of adding compressiong to HttpClient in this snippet.

A short example on how one can plug into the ambient logging and tracing system and besides just adding logging and tracing information (that ought to become visible in AppInsight too) also even modify the data in the classes. This is some copy-pastish code. See the link in class comment for well known "logging IDs".

/// <summary>
/// Enriches current HTTP activity.
/// The events to listen are at <see href="https://github.com/dotnet/corefx/blob/master/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs"/>.
/// </summary>
internal sealed class HttpRequestActivityEnricher: IObserver<DiagnosticListener>, IDisposable
{
    /// <summary>
    /// Listener subscriptions.
    /// </summary>
    private IList<IDisposable> Subscriptions { get; } = new List<IDisposable>();

   /// <summary>
    /// Listener options.
    /// </summary>
    private HttpRequestActivityEnricherOptions Options { get; }

   public HttpRequestActivityEnricher(IOptions<HttpRequestActivityEnricherOptions> options)
    {
        Options = options.Value;
    }

    /// <summary>
    /// Subscribes the enricher to all diagnostic listeners.
    /// </summary>
    public void SubscribeToAll()
    {
        Subscriptions.Add(DiagnosticListener.AllListeners.Subscribe(this));
    }


    /// <inheritdoc />
    public void Dispose()
    {
        foreach(IDisposable subscription in Subscriptions)
        {
            subscription.Dispose();
        }
    }


    /*[DiagnosticName("System.Net.Http.HttpRequestOut")]
    public void IsEnabled()
    {
        //As this is only enriching some HTTP headers and not producing anything, this is a no-op.
    }*/


    /// <summary>
    /// Called when a HTTP request that has started.
    /// </summary>
    /// <param name="request">The started HTTP request.</param>
    [DiagnosticName("System.Net.Http.HttpRequestOut.Start")]
    public void OnHttpRequestOutStart(HttpRequestMessage request)
    {
        if(Options.HostNames.Contains(request.RequestUri.Host))
        {
            foreach(var header in this.options.Headers)
            {
                if(request.Headers.TryGetValues(header, out var values))
                {
                    Activity.Current.AddTag($"{header}", string.Join(", ", values));
                }
            }
        }
    }


    /// <summary>
    /// Called when a HTTP request has stopped.
    /// </summary>
    /// <param name="request">The started HTTP request.</param>
    /// <param name="response">The response HTTP message.</param>
    /// <param name="requestTaskStatus">The HTTP task status.</param>
    [SuppressMessage("Microsoft.Usage", "CA1801:ReviewUnusedParameters", MessageId = "requestTaskStatus")]
    [DiagnosticName("System.Net.Http.HttpRequestOut.Stop")]
    public void OnHttpRequestOutStop(HttpRequestMessage request, HttpResponseMessage response, TaskStatus requestTaskStatus)
    {
        if(request != null && response != null && Options.SomethingSomething)
        {
            var activity = Activity.Current;
            if(activity != null)
            {
                if(response.Headers.TryGetValues("something", out var values))
                {
                    activity.AddTag("Activity Id", string.Join(", ", values));
                }

                if(response.Headers.TryGetValues("something", out values))
                {
                    activity.AddTag("Some other tag", string.Join(", ", values));
                }
            }
        }
    }


    /// <inheritdoc />
    void IObserver<DiagnosticListener>.OnCompleted()
    {
        //As this is only enriching some HTTP headers and not producing anything, this is a no-op.
    }


    /// <inheritdoc />
    void IObserver<DiagnosticListener>.OnError(Exception error)
    {
        //As this is only enriching some HTTP headers and not producing anything, this is a no-op.
    }


    /// <inheritdoc />
    void IObserver<DiagnosticListener>.OnNext(DiagnosticListener value)
    {
        if(value.Name == "HttpHandlerDiagnosticListener")
        {
            Subscriptions.Add(value.SubscribeWithAdapter(this));
        }
    }
}

//Configuring...
services.AddSingleton<HttpRequestActivityEnricher>();
        services.Configure<HttpRequestActivityEnricherOptions>(options =>
        {
            options.HostNames = new HashSet<string>
            {
                new Uri("localhost:123").Host
            };
        });

var serviceProvider = services.BuildServiceProvider();
serviceProvider.GetService<HttpRequestActivityEnricher>().SubscribeToAll();

<edit: Almost forgot, creating a new source seems to be as easy as
private static DiagnosticListener SomeDiagnosticsSource { get; } = new DiagnosticListener("SomeSource");

[veikkoeeva]

Distributed tracing and correlation through Service Bus messaging, an example how to connect to Service Bus tracing. Microsoft docs on distributed tracing on HTTP headers, currently more of an example how to do this in micro-services (notable the more standard headers to distribute correlation IDs are described at https://en.wikipedia.org/wiki/List_of_HTTP_header_fields, albeit with the previous middleware proxy these can be interchanged).

.NET Core SqlCommand has one example how to create DiagnosticsListener and log execution times (see also https://github.com/dotnet/corefx/search?utf8=%E2%9C%93&q=WriteCommandBefore&type=). Some examples, likely DelegateHandler has timing code too. :)

[xiazen]

"semantic logging on orleans internals", this could be a big project. I don't think we need to do this for all logging in orleans, but just some. So the questions which ones can benefit the most from semantic logging? In and out to external services, such as Azure table? I think if we can define this project more by listing the logs which can benefit most from semantic logging, it would be a good start.

[veikkoeeva]

Cross-referecing dotnet/extensions#526 here as Orleans follows closely ASP.NET Core configuration surface. This feature likely comes more popular and would-like-to-have once it's exposed in ASP.NET core easily.

[ReubenBond]

Closely related to #4992

An incremental approach is good. I added my thoughts to that issue.

[veikkoeeva]

Indeed closely related, thanks @ReubenBond. I'll cross-reference #3093 (comment) here too since it's basically the same thing and it might be beneficial to have the links quickly at hand.

[ghost]

We are marking this issue as stale due to the lack of activity in the past six months. If there is no further activity within two weeks, this issue will be closed. You can always create a new issue based on the guidelines provided in our pinned announcement.

[ghost]

This issue has been marked stale for the past 30 and is being closed due to lack of activity.