Byte217 - Logging - AOP and Metalama

As mentioned in the introduction, logging is helpful to track errors in a production environment and during debugging. Usually, this means we have to add logging statements to every function’s start and end, and when exceptions occur. This can be tedious and adds much extra code that doesn’t contain business logic.

The solution is to generate the code by using aspect classes.
With the Metalama Framework, you can write those aspect classes. It transforms the code at compile time. In our case, the aspect class adds code to log the method name, parameters, exceptions, and return values. The aspect is added as a C# Attribute.

With the Metalama Framework, inserting the attributes in bulk at compile time is also possible. We get the benefits of the added aspects without having to make changes to our existing code. This functionality is only supported in the paid version and during the trial period, but I will show you how.

To cover the majority of the logging, we need:

• The LogAttribute class
• ILoggable interface
• Fabric.cs, for applying the aspects in bulk

The Aspect class

The most important class is the LogAttribute class. The LogAttribute class uses the ILogger interface to log to the logging providers according to the configuration.

I have used an example from the Metalama website and extended it. The example on the Metalama website is very clear and explains in detail how the aspect classes work. I encourage you to have a look at it: https://doc.postsharp.net/metalama/examples/log

My version of the LogAttribute class logs ‘out’ and ‘ref’ parameters, it supports structured logging for Seq and it generates the minimal amount code without changing the existing functionality.

using Metalama.Framework.Aspects;
using Metalama.Framework.Code;
using Metalama.Framework.Diagnostics;
using Metalama.Framework.Eligibility;
using Microsoft.Extensions.Logging;
using Newtonsoft.Json;

namespace LoggingExample.Core.Attributes
{
    public class LogAttribute : MethodAspect
    {
#if DEBUG
        private static readonly string[] _excludeParameters = { "authorization" };
#else
        private static readonly string[] _excludeParameters = { "authorization", "password" };
#endif
        private static readonly DiagnosticDefinition<INamedType> _missingLoggerFieldError = new("LOG01", Severity.Error, "The type '{0}' must have a field 'ILogger _logger' or a property 'ILogger Logger'.");
        private static readonly DiagnosticDefinition<(DeclarationKind, IFieldOrProperty)> _loggerFieldOrIncorrectTypeError = new("LOG02", Severity.Error, "The {0} '{1}' must be of type ILogger.");

        public override void BuildAspect(IAspectBuilder<IMethod> builder)
        {
            var declaringType = builder.Target.DeclaringType;

            // Finds a field named '_logger' or a property named 'Logger'.
            IFieldOrProperty loggerFieldOrProperty = (IFieldOrProperty)declaringType.AllFields.OfName("_logger").SingleOrDefault() ?? declaringType.AllProperties.OfName("Logger").SingleOrDefault();

            // Report an error if the field or property does not exist.
            if (loggerFieldOrProperty == null)
            {
                builder.Diagnostics.Report(_missingLoggerFieldError.WithArguments(declaringType));
                return;
            }

            // Verify the type of the logger field or property.
            if (!loggerFieldOrProperty.Type.Is(typeof(ILogger)))
            {
                builder.Diagnostics.Report(_loggerFieldOrIncorrectTypeError.WithArguments((declaringType.DeclarationKind, loggerFieldOrProperty)));
                return;
            }

            // Override the target method with our template. Pass the logger field or property to the template.
            builder.Advice.Override(builder.Target, nameof(this.OverrideMethod), new { loggerFieldOrProperty });
        }

        public override void BuildEligibility(IEligibilityBuilder<IMethod> builder)
        {
            base.BuildEligibility(builder);

            // Now that we reference an instance field, we cannot log static methods.
            builder.MustNotBeStatic();
        }

        [Template]
        private static dynamic OverrideMethod(IFieldOrProperty loggerFieldOrProperty)
        {
            var logger = (ILogger)loggerFieldOrProperty.Value!;
            LogInputValues(logger);

            try
            {
                dynamic value = meta.Proceed();

                LogOutputValues(logger, value);
                return value;
            }
            catch (Exception exception)
            {
                LogException(logger, exception);
                throw;
            }
        }

        [Template]
        private static void LogInputValues(ILogger logger)
        {
            string className = meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified);
            string methodName = meta.Target.Method.Name;

            if (logger.IsEnabled(LogLevel.Debug))
            {
                // Remove output parameters
                var filteredParameters = meta.Target.Parameters.Where(i => !_excludeParameters.Contains(i.Name.ToLower()) && i.RefKind != RefKind.Out).ToList();
                if (filteredParameters.Count > 0)
                {
                    Dictionary<string, object> parameters = new();
                    foreach (var parameter in filteredParameters)
                    {
                        parameters.Add(parameter.Name, parameter.Value);
                    }

                    string str = JsonConvert.SerializeObject(parameters, Formatting.Indented);
                    LoggerExtensions.LogDebug(logger, "{Class}.{Method} {@InputParameters}", className, methodName, str);
                }
                else
                {
                    LoggerExtensions.LogDebug(logger, "{Class}.{Method}", className, methodName);
                }
            }
        }

        [Template]
        private static void LogOutputValues(ILogger logger, dynamic value)
        {
            if (logger.IsEnabled(LogLevel.Debug))
            {
                string className = meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified);
                string methodName = meta.Target.Method.Name;

                bool hasReturnValue = HasReturnValue(meta.Target.Method.ReturnType);

                // Remove input parameters
                var filteredParameters = meta.Target.Parameters.Where(i => !_excludeParameters.Contains(i.Name.ToLower()) &&
                                                                           (i.RefKind == RefKind.Out || i.RefKind == RefKind.Ref)).ToList();
                if (filteredParameters.Count > 0)
                {
                    Dictionary<string, object> parameters = new Dictionary<string, object>();
                    foreach (var parameter in filteredParameters)
                    {
                        parameters.Add(parameter.Name, parameter.Value);
                    }

                    string serializedParameters = JsonConvert.SerializeObject(parameters, Formatting.Indented);

                    if (hasReturnValue)
                    {
                        string str = JsonConvert.SerializeObject(value, Formatting.Indented);
                        LoggerExtensions.LogDebug(logger, "{Class}.{Method} returns: {@ReturnValue} {@OutputParameters}", className, methodName, str, serializedParameters);
                    }
                    else
                    {
                        LoggerExtensions.LogDebug(logger, "{Class}.{Method} returns: {@OutputParameters}", className, methodName, serializedParameters);
                    }
                }
                else
                {
                    if (hasReturnValue)
                    {
                        string str = JsonConvert.SerializeObject(value, Formatting.Indented);
                        LoggerExtensions.LogDebug(logger, "{Class}.{Method} returns: {@ReturnValue}", className, methodName, str);
                    }
                    else
                    {
                        LoggerExtensions.LogDebug(logger, "{Class}.{Method} returns no value", className, methodName);
                    }
                }
            }
        }

        [Template]
        private static void LogException(ILogger logger, Exception exception)
        {
            if (logger.IsEnabled(LogLevel.Error))
            {
                string className = meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified);
                string methodName = meta.Target.Method.Name;

                LoggerExtensions.LogError(logger, "{Class}.{Method} raised exception: {@Exception}", className, methodName, exception);
            }
        }

        private static bool HasReturnValue(IType returnType)
        {
            AsyncInfo asyncInfo = returnType.GetAsyncInfo();
            return !returnType.Is(typeof(void)) && !asyncInfo.ResultType.Is(typeof(void));
        }
    }
}

For every function that is decorated with the [Log] attribute logging code will be added. I have added the abstract class ServiceBase and the derived class ProjectsService in one code block for readability. Normally, I only add one class to one file.

using Microsoft.Extensions.Logging;

namespace LoggingExample.Services
{
    public abstract class ServiceBase
    {
	    protected DbContext _context;
        protected ILogger<ServiceBase> _logger;

        public ServiceBase(DbContext context, ILogger<ServiceBase> logger)
        {
        	_context = context;
            _logger = logger;
        }
    }

    public class ProjectsService : ServiceBase, IProjectsService
    {
        public ProjectsService(DbContext context, ILogger<ServiceBase> logger)
            : base(context, logger)
        {
        }

		[Log]
        public async Task<ActionResult<IEnumerable<Project>>> GetProjects(DateTime date)
        {
        	// get projects
            return await _context.GetProjects(date);
        }
}

This generates the following code for the GetProjects() method.

public async Task<ActionResult<IEnumerable<Project>>> GetProjects(DateTime date)
{
	var logger = (ILogger)this._logger;
	ILogger logger_1 = logger;
	if (logger_1.IsEnabled(LogLevel.Debug))
	{
		Dictionary<string, object> parameters = new();
		parameters.Add("date", date);
		string str = JsonConvert.SerializeObject(parameters, Formatting.Indented);
		LoggerExtensions.LogDebug(logger_1, "{Class}.{Method} {@InputParameters}", "ProjectsService", "GetProjects", str);
	}

	try
	{
		var value = await this.GetProjects_Source(authorization, date);
		ILogger logger_2 = logger;
		var value_1 = value;
		if (logger_2.IsEnabled(LogLevel.Debug))
		{
			string str_1 = JsonConvert.SerializeObject(value_1, Formatting.Indented);
			LoggerExtensions.LogDebug(logger_2, "{Class}.{Method} returns: {@ReturnValue}", "ProjectsService", "GetProjects", str_1);
		}

		return value;
	}
	catch (Exception exception)
	{
		ILogger logger_3 = logger;
		Exception exception_1 = exception;
		if (logger_3.IsEnabled(LogLevel.Error))
		{
			LoggerExtensions.LogError(logger_3, "{Class}.{Method} raised exception: {@Exception}", "ProjectsService", "GetProjects", exception_1);
		}

		throw;
	}
}

private async Task<ActionResult<IEnumerable<Project>>> GetProjects_Source(DateTime date)
{
	// get projects
    return await _context.GetProjects(date);
}

This code can be viewed and debugged if you add a configuration with the name ‘LamaDebug’ to your solution. When adding the configuration let it copy the setting from the Debug configuration. I added DEBUG to the conditional compiler symbols, so I won’t have to change my code when I switch between Debug and LamaDebug.

When compiling with the LamaDebug configuration it generates the .cs code in the obj/LamaDebug/metalama folder.
This is very helpful when you are developing aspect classes or to add breakpoints for debugging.

Bulk insert aspects at compile time

If the code base is large, it is still a lot of work to decorate every function of every class with a [Log] attribute. The Fabric class can do this for you.
Add the code below to a file named Fabric.cs and add it to the root of your project. During compilation the AmendProject method decides if the aspect should be added to the method that is compiled. In this case the [Log] attribute is added to every class that is derived from the abstract ServiceBase class.

Using an abstract class

using Metalama.Framework.Code;
using Metalama.Framework.Fabrics;

namespace LoggingExample.Services
{
    public class Fabric : ProjectFabric
    {
        public override void AmendProject(IProjectAmender amender)
        {
            amender.Outbound
                .SelectMany(compilation => compilation.GetDerivedTypes(typeof(ServiceBase)))
                .Where(type => (type.Accessibility is Accessibility.Public or Accessibility.Internal or Accessibility.PrivateProtected))
                .SelectMany(type => type.Methods)
                .Where(method => method.Accessibility == Accessibility.Public && method.Name != "ToString")
                .AddAspectIfEligible<LogAttribute>();
        }
    }
}

Using ILoggabble interface

In case you want to bulk insert aspects on classes that are partial, like Blazor components, you can add the ILoggable interface, and use this in the Fabric

namespace LoggingExample.Core.Logging
{
    public interface ILoggable<T> where T : class
    {
        public ILogger<T> Logger { get; set; }
    }
}

namespace LoggingExample.Blazor
{
    public partial class TimeDisplay : IDisposable, ILoggable<TimeDisplay>
    {
        [Inject]
        public ILogger<TimeDisplay> Logger { get; set; }

		public async Task<bool> IsTimeForBreak()
		{
			bool isTimeForBreak = _context.IsTimeForBreak();
			return isTimeForBreak
		}
	}
}

using Metalama.Framework.Code;
using Metalama.Framework.Fabrics;

namespace LoggingExample.Blazor
{
    public class Fabric : ProjectFabric
    {
        public override void AmendProject(IProjectAmender amender)
        {
            amender.Outbound
                .SelectMany(compilation => compilation.GetDerivedTypes(typeof(ILoggable<>)))
                .Where(type => (type.Accessibility is Accessibility.Public or Accessibility.Internal or Accessibility.PrivateProtected))
                .SelectMany(type => type.Methods)
                .Where(method => method.Accessibility == Accessibility.Public && method.Name != "ToString")
                .AddAspectIfEligible<LogAttribute>();
        }
    }
}

Conclusion

When using the Metalama framework, you can add an aspect class that will add additional code to your own code. In the free version, you will have to add the aspect to each of the method yourself, by adding the corresponding attribute. In the paid version you can use a Fabric class to have the aspects added to the methods that you have selected.