PostSharp6.3/Logging/Implementing Logging for a Distributed System

Implementing Logging for a Distributed System

A distributed system is composed of several applications calling each other to complete one operation. Each of these applications emits its own logs and often stores them in different locations. With distributed systems, logging is the easy part. What's much harder is to make sense of this ocean of logs from a logical point of view.

If you need to implement logging for a distributed system, the first step is to select a single location to store the logs. Dozens of solutions are available and PostSharp Diagnostics is agnostic about this choice.

The next challenge is to correlate the log records coming from different applications to get a logical view of all records relevant to the processing of a specific request. Typically, this means that you will need to set some HTTP header on client side and read it on server side. If you're using a different technology, such as WCF or MSMQ, you will need to take a different approach.

PostSharp Logging does not automatically add headers to cross-process messages, but it provides the necessary API to do so. It is structured on the HTTP Correlation Protocol specification.

This topic contains the following sections:

Generating hierarchical context ids

To correlate traces across processes, it is necessary to assign a proper identifier to each context and record. PostSharp Logging offers a suitable context identifier in the SyntheticId property. You can read this identifier from logSource.CurrentContext.SyntheticId or activity.Context.SyntheticId.

The default implementation of the SyntheticId property respects the Hierarchical Request-Id specification.

The most important benefit of this specification is that it is possible to select all children records of a logical distributed operation only by filtering by the beginning of the SyntheticId, e.g. in pseudo-SQL:

SQL
SELECT * FROM Records WHERE SyntheticId LIKE '|45ed51e.1.da4e9679%';

Additionally, our implementation generates sortables identifiers, so that ordering records by SyntheticId makes sense:

SQL
SELECT * FROM Records WHERE SyntheticId LIKE '|45ed51e.1.da4e9679%' ORDER BY SyntheticId ASC;

The filtering and ordering characteristics of the identifiers depend on the generation strategy, as explained below.

Comparing generation strategies

The generation strategy of the SyntheticId property dependends on several configuration properties: ContextIdGenerationStrategy, RootSyntheticId, and SyntheticIdFormatter .

ContextIdGenerationStrategy is the most important configuration option. It determines how the LoggingContext.Id property (a 64-bit integer) is generated. There are basically two stategies: global and hierarchical. They are compared in the next table.

Global Strategy

Hierarchical Strategy

Description

This strategy uses a single AppDomain-wide static 64-bit counter to generate the identifier. The SyntheticId is therefore composed of the RootSyntheticId (by default, a random 64-bit integer) followed by the 64-bit Id itself.

The Id property is generated using a counter in the scope of the parent context. If there is no parent context, the global strategy is used. Therefore, the SyntheticId property is composed of the SyntheticId of the parent context, plus the Id of the current context.

Length of generated identifiers

Short.

Potentially very long.

Performance

May cause thread contention on highly loaded systems because several threads may be trying to get exclusive access to the global counter at the same time.

No thread contention issue, but more CPU time required to render the id.

Ordering

Preserving time, but not causality (parallel async calls are mixed).

Preserving causality, but not time (parallel async calls are separated from each other).

Filtering

Only based on cross-process boundaries (see discussion on SyntheticParentId below).

Based on any context (external activity, method, custom in-process activity).

Setting the ParentId of a request

When the logical parent of an activity stems from an external process, you need to read the parent id from the incoming headers, open a new activity (see Working with Custom Activities), and set the OpenActivityOptions.SyntheticParentId property.

When this property is set, the SyntheticId will start with the value of the SyntheticParentId property, and the in-process parent activity, if any, will be ignored.

Marking a property as cross-process

You can use the LoggingProperty.IsBaggage property to mean that a LoggingProperty should be carried across process boundaries. This flag is not used by PostSharp Logging itself. It exists to help you implement the process of writing the proper HTTP headers when emitting an HTTP request.

Example

The following code snippet shows a possible server-side implementation of the HTTP Correlation Protocol and Hierarchical Request-Id specifications. It is based on a MethodInterceptionAspect aspect applied to the HttpClient class.

C#
using System;
using System.Collections.Generic;
using System.Net.Http;
using System.Runtime.Serialization;
using System.Text;
using System.Threading.Tasks;
using ClientExample;
using PostSharp.Aspects;
using PostSharp.Patterns.Diagnostics;
using PostSharp.Patterns.Formatters;
using PostSharp.Serialization;
using static PostSharp.Patterns.Diagnostics.SemanticMessageBuilder;

// The following attribute intercepts all calls to the specified methods of HttpClient.
[assembly: InstrumentOutgoingRequestsAspect(
    AttributeTargetAssemblies = "System.Net.Http",
    AttributeTargetTypes = "System.Net.Http.HttpClient",
    AttributeTargetMembers = "regex:(Get*|Delete|Post|Push|Patch)Async")]

namespace ClientExample
{
    [PSerializable]
    internal class InstrumentOutgoingRequestsAspect : MethodInterceptionAspect
    {
        private static readonly LogSource logSource = LogSource.Get();

        public override async Task OnInvokeAsync(MethodInterceptionArgs args)
        {
            var http = (HttpClient) args.Instance;
            var verb = Trim(args.Method.Name, "Async");

            using (var activity = logSource.Default.OpenActivity(Semantic(verb, ("Url", args.Arguments[0]))))
            {
                try
                {
                    // TODO: this implementation conflicts with System.Diagnostics.Activity and therefore Application Insights.


                    // Remove headers.
                    http.DefaultRequestHeaders.Remove("Request-Id");
                    http.DefaultRequestHeaders.Remove("Correlation-Context");


                    // Set Request-Id header.
                    http.DefaultRequestHeaders.Add("Request-Id", activity.Context.SyntheticId);


                    // Generate the Correlation-Context header.
                    UnsafeStringBuilder correlationContextBuilder = null;
                    var propertyNames = new HashSet<string>();
                    try
                    {
                        activity.Context.ForEachProperty((LoggingProperty property, object value, ref object _) =>
                        {
                            if (!property.IsBaggage || !propertyNames.Add(property.Name)) return;

                            if (correlationContextBuilder == null)
                            {
                                propertyNames = new HashSet<string>();
                                correlationContextBuilder = new UnsafeStringBuilder(1024);
                            }

                            if (correlationContextBuilder.Length > 0)
                            {
                                correlationContextBuilder.Append(", ");
                            }

                            correlationContextBuilder.Append(property.Name);
                            correlationContextBuilder.Append('=');

                            var formatter =
                                property.Formatter ?? LoggingServices.Formatters.Get(value.GetType());

                            formatter.Write(correlationContextBuilder, value);
                        });

                        if (correlationContextBuilder != null)
                        {
                            http.DefaultRequestHeaders.Add("Correlation-Context", correlationContextBuilder.ToString());
                        }
                    }
                    finally
                    {
                        correlationContextBuilder?.Dispose();
                    }


                    var t = base.OnInvokeAsync(args);

                    // We need to call Suspend/Resume because we're calling LogActivity from an aspect and 
                    // aspects are not automatically enhanced.
                    // In other code, this is done automatically.
                    if (!t.IsCompleted)
                    {
                        activity.Suspend();
                        try
                        {
                            await t;
                        }
                        finally
                        {
                            activity.Resume();
                        }
                    }


                    var response = (HttpResponseMessage) args.ReturnValue;


                    if (response.IsSuccessStatusCode)
                    {
                        activity.SetOutcome(LogLevel.Info, Semantic("Succeeded", ("StatusCode", response.StatusCode)));
                    }
                    else
                    {
                        activity.SetOutcome(LogLevel.Warning, Semantic("Failed", ("StatusCode", response.StatusCode)));
                    }
                }
                catch (Exception e)
                {
                    activity.SetException(e);
                    throw;
                }
                finally
                {
                    http.DefaultRequestHeaders.Remove("Request-Id");
                }
            }
        }

        private static string Trim(string s, string suffix)
            => s.EndsWith(suffix) ? s.Substring(0, s.Length - suffix.Length) : s;
    }
}

Here is a client-side implementation of the same protocol. It is based on an ASP.NET Action Filter. The filter needs to be added in the Startup.ConfigureServices method.

C#
using System;
using System.Collections.Generic;
using System.Net;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Mvc.Filters;
using PostSharp.Patterns.Diagnostics;
using static PostSharp.Patterns.Diagnostics.SemanticMessageBuilder;

namespace MicroserviceExample
{
    [Log(AttributeExclude = true)]
    public class LoggingActionFilter : IAsyncActionFilter
    {
        private static readonly LogSource logger = LogSource.Get();

        public async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
        {
            // Read the Request-Id header so we can assign it to the activity.
            string parentOperationId = context.HttpContext.Request.Headers["Request-Id"];


            OpenActivityOptions options = default;

            // Set the parent id.
            if (!string.IsNullOrEmpty(parentOperationId))
            {
                options.SyntheticParentId = parentOperationId;
            }
            else
            {
                options.IsSyntheticRootId = true;
            }

            // Process cross-context properties (aka baggage).
            string correlationContext = context.HttpContext.Request.Headers["Correlation-Context"];
            if (!string.IsNullOrEmpty(correlationContext))
            {
                var properties = new List<LoggingProperty>();
                foreach (var pair in correlationContext.Split(',', StringSplitOptions.RemoveEmptyEntries))
                {
                    var posOfEqual = pair.IndexOf('=');
                    if (posOfEqual <= 0) continue;
                    var propertyName = pair.Substring(0, posOfEqual);
                    var propertyValue = pair.Substring(posOfEqual + 1);
                    properties.Add(new LoggingProperty(propertyName, propertyValue) {IsBaggage = true});
                }

                options.Properties = properties.ToArray();
            }

            var request = context.HttpContext.Request;
            using (var activity = logger.Default.OpenActivity(Semantic("Request", ("Path", request.Path),
                ("Query", request.QueryString), ("Method", request.Method)), options))
            {
                try
                {
                    await next();

                    var response = context.HttpContext.Response;

                    if (response.StatusCode >= (int) HttpStatusCode.OK && response.StatusCode <= 299)
                    {
                        // Success.
                        activity.SetOutcome(LogLevel.Info, Semantic("Success", ("StatusCode", response.StatusCode)));
                    }
                    else
                    {
                        // Failure.
                        activity.SetOutcome(LogLevel.Warning, Semantic("Failure", ("StatusCode", response.StatusCode)));
                    }
                }
                catch (Exception e)
                {
                    activity.SetException(e);
                }
            }
        }
    }
}