PostSharp6.4/Logging/Choosing Which Requests to Log

Choosing Which Requests to Log

PostSharp Logging makes it so easy to add logging to your application that you can easily end up capturing gigabytes of data every minute. As it goes, most of this data won't ever be useful, but you still need to pay for storage and bandwidth. The ability to trace an application at a high level of detail is very useful, but it is important to be able to select when you want to log.

If you are running a web application, it is probably useless to log every single request with the highest level of detail, especially for request types that are served 100 times per second. Therefore, it is important to be able to decide, at run-time, which requests need to be logged. You may choose to disable logging by default and to enable logging only for select requests only.

The following table describes a few example strategies:

Strategy

Description

Random sampling

You decide, based on a randomly generated number, whether the current request should be logged. The problem of this approach is that frequently-served requests may be overrepresented, and rarely-served requests may be completely absent from the log.

Time window sampling

You log the given request type once per time period (e.g. per 200 ms resulting in maximum 5 requests per second) and ignore all other requests. This approach still results in semi-random sampling and addresses the downside of the previous strategy. However, the efficacy of this approach heavily depends on an algorithm that categorizes request types. If multiple requests of the same type are done in rapid succession, the last request has a lower probability of being logged.

Suspect requests

You log only requests that are likely to fail based on the path, the query string, the user name, the client IP, or any other piece of information available when the request is accepted. The "suspicion level" of a request can be coded manually or could come from statistical processing (AI-based or not) of data of your APM.

To selectively enable logging at request level

  1. Disable detailed logging at global level.

    C#
    LoggingServices.DefaultBackend.DefaultVerbosity.SetMinimalLevel( LogLevel.Warning );
  2. Create a LoggingVerbosityConfiguration by calling the CreateVerbosityConfiguration() method. This LoggingVerbosityConfiguration will be used by all requests where you want to enable logging. Store it in a field. Note that the LoggingVerbosityConfiguration is a memory-heavy type, so you should avoid creating one instance for every request.

    By default, the verbosity is set to Debug. You can configure the LoggingVerbosityConfiguration as needed.

  3. Intercept the request before it is passed to your application code (typically using an ASP.NET Action Filter or a WCF Behavior), decide whether the request should be logged, and call the [M:PostSharp.Patterns.Diagnostics.LoggingVerbosityConfiguration.Use()] method. Dispose the returned token once the request processing has completed.

Example

The following code snippet is an ASP.NET Action Filter that enables detailed logging for a random 10% sample of requests.

C#
using System;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Mvc.Filters;
using PostSharp.Patterns.Diagnostics;

namespace MicroserviceExample
{
    [Log(AttributeExclude = true)]
    public class SampledLoggingActionFilter : IAsyncActionFilter
    {
        private static readonly Random random = new Random();
        private static LoggingVerbosityConfiguration verbosityManager;

        public static void Initialize( LoggingBackend backend )
        {
            verbosityManager = backend.CreateVerbosityConfiguration();
        }

        public static bool IsInitialized => verbosityManager != null;

        private static bool IsLogged(ActionExecutingContext context)
        {
            lock (random)
            {
                // Log 10% of requests.
                return random.NextDouble() < 0.1;
            }
        }

        public async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
        {

            if ( IsInitialized && IsLogged(context))
            {
                using ( verbosityManager.Use() )
                {
                    await next();
                }
            }
            else
            {
                await next();
            }

        }
    }
}