Search code examples
c#asp.net.netaop

About logging every calling of a method in AOP way


I want to create a logging system for my project. And I want it to do in AOP way. Need to log every executed method with params and returned value. How I understand, it can be achieved via Interceptors. I have created a pet project for it. It almost works. The problem which I have met is how to understand from logs what are were executed during one request and what are were executed during another request? F.e. I have asp.net application. Users come to the application. I log everything. But I don't understand what one concrete user did. I just see in logs that one method was executed then another method was executed and so on. But how to define all executed methods which belong to concrete request?

Update: I know about filters in ASP.Net. And I use it for controllers. But I want to log services and data access layer too.

Another Update: nvoigt's answer works. Thanks nvoigt a lot!

protected void Application_Start()
    {
        AreaRegistration.RegisterAllAreas();
        GlobalConfiguration.Configure(WebApiConfig.Register);
        FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
        RouteConfig.RegisterRoutes(RouteTable.Routes);
        BundleConfig.RegisterBundles(BundleTable.Bundles);

        var builder = new ContainerBuilder();
        var config = GlobalConfiguration.Configuration;
        builder.RegisterApiControllers(Assembly.GetExecutingAssembly());
        builder.RegisterType<ItemService>().As<IItemService>().EnableInterfaceInterceptors().InterceptedBy(typeof(CallLogger)).InstancePerRequest();
        builder.RegisterType<ItemRepository>().As<IItemRepository>().EnableInterfaceInterceptors().InterceptedBy(typeof(CallLogger)).InstancePerRequest();
        builder.RegisterType<CallLogger>().AsSelf().InstancePerRequest();
        var container = builder.Build();
        config.DependencyResolver = new AutofacWebApiDependencyResolver(container);
    }

How you see, CallLoger has per request lifetime. And I have added Guid scopeId property To CallLogger

public class CallLogger : IInterceptor
{
    private readonly string _path = @"D:\1.txt";
    private readonly Guid _scopeId;
    public CallLogger()
    {
        _scopeId = Guid.NewGuid();
    }

    public void Intercept(IInvocation invocation)
    {
        string message = String.Format("{0}: {1} - Calling method {2} with parameters {3}... ",
            _scopeId,
            invocation.TargetType.FullName, invocation.Method.Name,
            string.Join(", ", invocation.Arguments.Select(a => a)));

        string[] m1 = { message };

        File.AppendAllLines(_path, m1);

        invocation.Proceed();

        List<string> m2 = new List<string>();

        if (invocation.ReturnValue is IEnumerable)
        {
            m2.Add(String.Format($"{_scopeId}: Done {invocation.TargetType.FullName} - {invocation.Method.Name}: result was"));
            foreach (var rv in (IEnumerable)invocation.ReturnValue)
            {
                m2.Add(rv.ToString());
            }
        }
        else
        {
            m2.Add(String.Format($"{_scopeId}: Done {invocation.TargetType.FullName} - {invocation.Method.Name}: result was {invocation.ReturnValue}"));
        }

        File.AppendAllLines(_path, m2);
    }
}

Now my logs with scopeId:

fd35e0f3-a162-48f9-9d69-b39c601513a2: Core.ItemService - Calling method Get with parameters 1... 
fd35e0f3-a162-48f9-9d69-b39c601513a2: Core.Repositories.ItemRepository - Calling method Get with parameters 1... 
fd35e0f3-a162-48f9-9d69-b39c601513a2: Done Core.Repositories.ItemRepository - Get: result was Id is 1, SomeProperty is Property1, AnotherProperty is Another1
fd35e0f3-a162-48f9-9d69-b39c601513a2: Done Core.ItemService - Get: result was Id is 1, SomeProperty is Property1, AnotherProperty is Another1
1ed6bfd7-f786-4397-905e-6ba7027bdd55: Core.ItemService - Calling method Get with parameters 5... 
1ed6bfd7-f786-4397-905e-6ba7027bdd55: Core.Repositories.ItemRepository - Calling method Get with parameters 5... 
1ed6bfd7-f786-4397-905e-6ba7027bdd55: Done Core.Repositories.ItemRepository - Get: result was Id is 5, SomeProperty is Property5, AnotherProperty is Another5
1ed6bfd7-f786-4397-905e-6ba7027bdd55: Done Core.ItemService - Get: result was Id is 5, SomeProperty is Property5, AnotherProperty is Another5

Solution

  • You were very vague in what you actually did so this answer is kinda just as vague in what you need to do:

    Each log entry has to contain an identifier so you can group your log entries by identifier and basically get one group of logs for each call to your controller (the controller logs, the logs of the service layer, repository all grouped together by their initial entry).

    You already have an instance that holds data per call, it's your dependency injection container that has a scope per call. You need to have a class in there that holds your scope specific data (for example just a Guid.NewGuid() per scope) and your logger has to have access to that class by means of your dependency injection framework. Then your logger can append that identifier to your logs and you can later group by it.