Suggestions on a design pattern for logging in .NET?

Hello! I’m starting a personal project in .NET.

For a logging solution, I want to achieve something similar to what I have in a Python REST API I wrote a while back using the decorator pattern (example in the image).

In the example, the outter “log” function receives the logger I want to use, the decorator function receives a function and returns the decorated function ready to be called (this would be the decorator), and the wrapper function receives the same arguments as the function to be decorated (which is a generic (*args, **kwargs) ofc, because it’s meant to decorate any function) and returns whatever the return type of the function is (so, Any). In lines 17 - 24 I just call the passed in “func” with the passed in arguments, but in between I wrap it in a try except block and log that the function with name func.__name__ started or finished executing. In practice, using this decorator in Python looks like this:


<span style="color:#323232;">import logging
</span><span style="color:#323232;">from my.decorator.module import log
</span><span style="color:#323232;">
</span><span style="color:#323232;">_logger = logging.getLogger(__name__)
</span><span style="color:#323232;">
</span><span style="color:#323232;">@log(_logger)
</span><span style="color:#323232;">def my_func(arg1: Arg1Type, arg2: Arg2Type) -> ReturnType:
</span><span style="color:#323232;">    ...
</span>

Ofc it’s a lot simpler in Python, however I was wondering if it would be possible or even recommended to attempt something similar in C#. I wouldn’t mind having to call the function and wrap it manually, something like this:

return RunWithLogs(MyFunction, arg1, arg2);

What I do want to avoid is manually writing the log statements inside the service’s business logic, or having to write separate wrappers for each method I want to log. Would be nice to have one generic function or class that I can somehow plug-in to any method and have it log when the call starts and finishes.

Any suggestions? Thanks in advance.

atheken,

Not that I would recommend it, but you can also try something like extension methods on Func.


<span style="color:#323232;">public static RunAndLog(this Func<T> f) {
</span><span style="color:#323232;"> LogStart(f);
</span><span style="color:#323232;">var x = f();
</span><span style="color:#323232;">LogEnd(f);
</span><span style="color:#323232;">return x;
</span><span style="color:#323232;">}
</span>

I think you may have enough diagnostic info with reflection to write something meaningful, and you can add overloads with generic parameters for the func params, and/or Action.

You may also create an IDisposable that logs a start and end statement around a function call:


<span style="color:#323232;">using var _ = CallLogger(“func name”) {
</span><span style="color:#323232;">f();
</span><span style="color:#323232;">}
</span>

Personally, I wouldn’t do either of these. This level of logging produces an enormous amount of noise, making finding signal very difficult. I would focus more energy on writing unique and helpful messages where they are important, and using git grep to find the related source code when they show up in production logs (assuming you don’t log a stack trace). This level of call logging can be temporarily useful while debugging or reasoning through an app, but rarely belongs in production.

RonSijm, (edited )
@RonSijm@programming.dev avatar

The current answers using a Func or an Action are correctish, but with that approach you will have logging cross-cutting hard-wired into all your classes before invoking the methods.

If you want true AOP or decorators, you probably want to use Type Interceptors. And Castle DynamicProxy. See: autofac.readthedocs.io/en/…/interceptors.htmlblog.zhaytam.com/…/aspnetcore-dynamic-proxies-for…

A dynamic proxy will give you a method like this:


<span style="color:#323232;">public void Intercept(IInvocation invocation)
</span><span style="color:#323232;">{
</span><span style="color:#323232;">  _output.Write("Calling method {0} with parameters {1}... ",
</span><span style="color:#323232;">    invocation.Method.Name,
</span><span style="color:#323232;">    string.Join(", ", invocation.Arguments.Select(a => (a ?? "").ToString()).ToArray()));
</span><span style="color:#323232;">
</span><span style="color:#323232;">  invocation.Proceed();
</span><span style="color:#323232;">
</span><span style="color:#323232;">  _output.WriteLine("Done: result was {0}.", invocation.ReturnValue);
</span><span style="color:#323232;">}
</span>

Intercept is called before invoking a method, you can do stuff before the method starts, then you call invocation.Proceed(); - that invokes the method, and then you can log the result.

Note that your class methods either need to be virtual, or it needs to have an interface, I’d suggest an interface.

This way you can wire the logging part in through dependency injection in your container, and your classes itself don’t contain logging cross-cutting logic

Logging wise, I’m not sure how familiar you are with dotnet, as you’re saying you’re just starting, I’d suggest inside your classes you stick with Microsoft.Extensions.Logging.Abstractions - so your classes - lets say a class MyService - would be

public class MyService(Microsoft.Extensions.Logging.ILogger<MyService> logger) { }

Then I’d suggest Serilog to use as concrete logger. You’d wire that in with:


<span style="color:#323232;">     var configuration = new ConfigurationBuilder()
</span><span style="color:#323232;">        .SetBasePath(Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location)!)
</span><span style="color:#323232;">        .AddJsonFile("appsettings.json")
</span><span style="color:#323232;">        .Build();
</span><span style="color:#323232;">
</span><span style="color:#323232;">    services.AddLogging(loggingBuilder =>
</span><span style="color:#323232;">    {
</span><span style="color:#323232;">        var logger = new LoggerConfiguration()
</span><span style="color:#323232;">            .ReadFrom.Configuration(configuration)
</span><span style="color:#323232;">            .CreateLogger();
</span><span style="color:#323232;">
</span><span style="color:#323232;">        loggingBuilder.AddSerilog(logger, dispose: true);
</span><span style="color:#323232;">    });
</span>

Sirilog is a very extendable framework that comes with 100s of different Sinks so you can very easily wire in a different output target, or wire in different enrichers without modifying any of your existing code

pips34,

Beautiful! I only reply just now because I JUST got it working. This is exactly what I was looking for, thank you sooo much :) I’m keeping both approaches in a lil template project I have, and definitely checking Serilog next!

LodeMike,

Hi. Is that Atom/Pulsar?

pips34,

Hi, my IDE is PyCharm with the Material theme

https://programming.dev/pictrs/image/1e77f159-2813-49a2-9c12-99dda41e1eee.png

Lmaydev, (edited )

It’s certainly possible. You could use the Action and Func delegates.


<span style="color:#323232;">TReturn RunWithLog<T, TResult>(ILogger logger, Func<T, TResult> function, T parameter1)
</span><span style="color:#323232;">{
</span><span style="color:#323232;">    logger.LogInformation(....);
</span><span style="color:#323232;">    return function(parameter1);
</span><span style="color:#323232;">}
</span><span style="color:#323232;">
</span><span style="color:#323232;">void RunWithLog<T>(ILogger logger, Action<T> function, T parameter1)
</span><span style="color:#323232;">{
</span><span style="color:#323232;">    logger.LogInformation(....);
</span><span style="color:#323232;">    function(parameter1);
</span><span style="color:#323232;">}
</span>

You’d need to implement one for each number of parameters you want to accept.

You could also return a new func or action that contains the code in those methods to be called repeatedly. But I don’t think there’d be any advantage to doing it that way. I guess you could then pass it as an argument.


<span style="color:#323232;">Action<T> BuildRunWithLog<T>(ILogger logger, Action<T> function)
</span><span style="color:#323232;">{
</span><span style="color:#323232;">    return (T parameter1) => 
</span><span style="color:#323232;">    {
</span><span style="color:#323232;">        logger.LogInformation(....);
</span><span style="color:#323232;">        function(parameter1);
</span><span style="color:#323232;">    }
</span><span style="color:#323232;"> }
</span>

Wrote that from memory so syntax may be wrong.

pips34,

Love it! Works great for me, since most of my services receive only 2 params, and even if I didn’t, having 2 or 3 wrappers is no big deal. Tysm! :)

Lmaydev,

No worries mate 🙂

theit8514,

The primary issue with this approach is that you’ll need a RunWithLog for each number of parameters. Which is why Func and all the ones in between exists. learn.microsoft.com/en-us/dotnet/api/system?view=…

Lmaydev,

Yeah I did say that. It’s a pain but chances are you only need 5 or 6.

You could do it with reflection and params but then you lose type safety etc.

theit8514,

C# does not really implement decorators like that, which can execute autonomously. You would still need to wrap all the functions you want to call.

You can wrap the action using a Func<> or Action, and get the calling member name (e.g. name would be ‘Main’). The Arguments are a pain, as you have to drill down the Expression tree to get them. This case only handles ConstantExpression values, you would also need to handle MemberExpression and probably others.


<span style="color:#323232;">using System.Linq.Expressions;
</span><span style="color:#323232;">using System.Runtime.CompilerServices;
</span><span style="color:#323232;">
</span><span style="color:#323232;">    public static void Main()
</span><span style="color:#323232;">    {
</span><span style="color:#323232;">        var n = LogWrapper(() => MyMethod("Hello, World!"));
</span><span style="color:#323232;">        Console.WriteLine(n);
</span><span style="color:#323232;">    }
</span><span style="color:#323232;">
</span><span style="color:#323232;">    private static int MyMethod(string test)
</span><span style="color:#323232;">    {
</span><span style="color:#323232;">        Console.WriteLine(test);
</span><span style="color:#323232;">        return 42;
</span><span style="color:#323232;">    }
</span><span style="color:#323232;">
</span><span style="color:#323232;">    private static T LogWrapper(Expression> func, [CallerMemberName] string name = null)
</span><span style="color:#323232;">    {
</span><span style="color:#323232;">        // Do begin logging
</span><span style="color:#323232;">        var body = func.Body as MethodCallExpression;
</span><span style="color:#323232;">        var firstArgument = body?.Arguments.First() as ConstantExpression;
</span><span style="color:#323232;">
</span><span style="color:#323232;">        Console.WriteLine("name={0} param={1}", name, firstArgument?.Value);
</span><span style="color:#323232;">
</span><span style="color:#323232;">        var result = func.Compile().Invoke();
</span><span style="color:#323232;">
</span><span style="color:#323232;">        // Do end logging
</span><span style="color:#323232;">        Console.WriteLine("end name={0}", name);
</span><span style="color:#323232;">        return result;
</span><span style="color:#323232;">    }
</span>
Lmaydev,

Won’t you need to handle all the different expressions the parameter could be with this method? It won’t always be a constant right?

theit8514,

Yes, as I stated other expression types might be needed. You could also wrap the argument expression in Expression.Lambda() and execute it to get the value. None of these options are necessarily fast, and you’ll likely get double executions which could lead to unanticipated side effects.

Lmaydev,

I think taking the parameters as parameters and creating a function for each parameter count is better then you can just call the func/action normally.

  • All
  • Subscribed
  • Moderated
  • Favorites
  • •
  • csharp@programming.dev
  • ngwrru68w68
  • DreamBathrooms
  • thenastyranch
  • magazineikmin
  • InstantRegret
  • GTA5RPClips
  • Youngstown
  • everett
  • slotface
  • rosin
  • osvaldo12
  • mdbf
  • kavyap
  • cubers
  • megavids
  • modclub
  • normalnudes
  • tester
  • khanakhh
  • Durango
  • ethstaker
  • tacticalgear
  • Leos
  • provamag3
  • anitta
  • cisconetworking
  • JUstTest
  • lostlight
  • All magazines
    •