Hello,

Sometimes there is a moment when you take a look at your code and you feel that it is almost perfect. None of the extra lines of code is added, everything seems to be in right place, but something is holding you and can't let you go. Did I forget something? Ah, yes, logging...

Problem

And here we go, in best case scenario clean and pretty method goes like this:

public override Task InvokeAsync()
{
    Logger.Info("Start logging something");

    var chatId = _message.Chat.Id;
    var taskName = $"SendPhrase_{chatId}";

    if (CanScheduleTask(taskName))
       TaskEntity
          .Create(taskName)
          .WithAction(async () => await SendPhrase(chatId))
          .WithRecurrence(RecurrenceType.Random)
          .WithExecutionTime(DateTime.Now)
          .Schedule();

    Logger.Info("Stop logging");
    return Task.FromResult(_message.From.Username);
}

Not so pretty, huh? But is there a way to hide it somewhere? Maybe it is possible through attributes?

[Log("Here goes the logging")]
public override Task InvokeAsync()
{
    var chatId = _message.Chat.Id;
    var taskName = $"SendPhrase_{chatId}";

    if (CanScheduleTask(taskName))
       TaskEntity
          .Create(taskName)
          .WithAction(async () => await SendPhrase(chatId))
          .WithRecurrence(RecurrenceType.Random)
          .WithExecutionTime(DateTime.Now)
          .Schedule();

    return Task.FromResult(_message.From.Username);
}

Better, right?

Let's begin with the easiest, attribute.

public class LogAttribute : Attribute
{
   public string Message { get; set; }

   public LogAttribute(string message)
   {
      Message = message;
   }
}

Method interception

My guess was to intercept method invocation and get the result of execution. Castle.DynamicProxy will help us with this, it will be the proxy between class and logging logic. This library can sound familiar if you are using Moq for unit tests.

We need to create Interceptor class and inherit it from IInterceptor interface. It will be our base class. Let's declare instructions about what are we going to do during interception and before/after invocation.

public abstract class Interceptor : IInterceptor
{
    public void Intercept(IInvocation invocation)
    {
        invocation.Proceed();

        ExecuteAfter(invocation);
    }

    protected abstract void ExecuteAfter(IInvocation invocation);
}

Because we are interested in invocation results, we need to override ExecuteAfter method in our interceptor implementation.

Next, let's create a class describing what and how we going to log.

public class TaskEntityInterceptor : Interceptor
{
    protected override void ExecuteAfter(IInvocation invocation)
    {
        var message = InterceptorHelpers
            .GetMessageFromAttribute(invocation.Method);

        if (string.IsNullOrEmpty(message))
            return;

         var target = invocation.InvocationTarget as TaskEntity;
         var method = invocation.Method;

         // Here can be any type of logging you like. E.g. log4net, NLog, etc
         Console.WriteLine(string.Format(message, target.Name,  target.ExecutionTime));
        }
    }

This class is going to check if invoked method got Log attribute, compose it to logging entity with a message from attribute, method name, and value of the class property.

To make interception working we need to specify interception class when creating an instance of a class that needs to be logged.

public static TaskEntity Create(string name)
{
    var pr = new ProxyGenerator();
    var entity = (TaskEntity) pr.CreateClassProxy(typeof(TaskEntity), new object[] { name },    new TaskEntityInterceptor());

    return entity;
}

As I'm using a builder pattern, it's not a problem for me. Every time we create TaskEntity instance we actually create a class with a proxy between. So, when the class method with Log attribute invoked we will create a log record.

For attribute like this:

[Log("{0}: Execution time set to: {1}")]

Record will look like:

SomeName: Execution time set to: 05/12/2021 22:12:45

Example project: https://github.com/Kentarre/AttributeBasedLoggingDemo

Have fun. 😉