Logging Proxy in C#

• Download source

Logging Interface Usage for the Purpose of Documenting It

It all started as a practical task. I was approached by project leadership with a practical problem. In one of our bank applications, we had on certain place interface IA which was implemented by a certain communication module A. Class A was doing very complex communication over specific bank protocol. They were considering adopting the application for a new customer by replacing communication module A with new module A2.

The problem was that the only valid documentation that existed for interface IA is the code itself. Other documentation is outdated, and people that implemented module A are no longer with the company.

So, we needed to document interface IA. I was asked to log ALL communication on interface IA, with ALL incoming and outgoing parameters, with timestamps, with proper method invocation sequence, and that Log will become the documentation for the interface IA.

I started to browse the code of IA and A. IA was complex, with many methods with complex parameters, like a list of objects that contained other objects. It became obvious that a naïve approach, like inserting logging code into class A is not a good idea. My concerns were:

1. didn’t want to interfere with complex code that was working well;
2. once documenting was finished, all logging code needed to be suspended, but ready for possible activation if needed again;
3. I would be inserting a practically same type of logging code at multiple places/methods, better if it can be centralized.

So, I decided to solve a problem by building a Logging Proxy.

Proxy Design Pattern

For those that are not familiar with Proxy Design Pattern [1], I will just shortly outline the idea. So, we want to replace situations like this:

With a new design like this:

The aim is to build LoggingProxyIA (that implements interface IA) that will intercept all calls to class A, forward them to class A, and in the meantime log all inputs and outputs to any method of class A. It is important that LoggingProxyIA be as transparent as possible so that it does not interfere with program logic in any way. Application talks to interface IA and is not aware if it talks to LoggingProxyIA or class A. Once logging is finished, LoggingProxyIA will be removed, and the application will again talk to object A directly. Since LoggingProxyIA class stays in the source code, at any point in time, logging can be activated again.

There are two ways to intercept and log in class LoggingProxyIA:

1. to implement every method of IA manually in LoggingProxyIA and log and forward calls to A;
2. to use Reflection technology to generically intercept methods calls

Obviously, approach 2) is better, since we will implement our logging in only one place and will create reusable code.

Intercepting Method Calls

So, I needed a mechanism to intercept method calls. Fortunately, such a library already exists, it is called System.Reflection.DispatchProxy [2]. It provides a mechanism for instantiating proxy objects and handling their method dispatch. It has a very simple public interface:

public abstract class DispatchProxy
{
    protected DispatchProxy();

    public static T Create<T, TProxy>() where TProxy : DispatchProxy;
    
    protected abstract object? Invoke(MethodInfo? targetMethod, object?[]? args);
}

This class is designed to be inherited by your real proxy implementation and has a protected constructor. Let’s go over the important methods.

Create Method

Create is where the hard work of creating the proxy object is done. But the method signature is a bit misleading. If we look at the method signature:

public static T Create<T, TProxy>() where TProxy : DispatchProxy; 

It says that it returns the object of type T. But the truth is the returned object implements interface T and extends TProxy. So, it is possible to cast the returned object to TProxy type, which is not obvious at all from the method signature. And I will be using that feature in my code at location (555).

How do we know that I am telling the truth? First of all, if you carefully read the documentation [3], it does mention it in one place. Secondly, you can use a decompiler like dotPeek [4] to look into the source code of that class. With its magic work, it will provide you even with the comments in the code. Here is what I found with dotPeek:

You can browse the decompiled code to verify that it really does what the comment says.

It is also interesting to look with dotPeek what kind of checks Create method is doing so that you know what are limitations on provided parameters T and TProxy.

The bottom line is Create method will create us a Proxy object that we need, and the resulting object is of both type T and TProxy.

Invoke Method

Invoke method is where our intercept will happen and is the main purpose of using this class System.Reflection.DispatchProxy. Here is its signature:

protected abstract object? Invoke(System.Reflection.MethodInfo? targetMethod, 
      object?[]? args);

In your proxy implementation, we need to override this method and do our loggings. In the following code segment, we outline the principle:

protected override object Invoke(MethodInfo targetMethod, object[] args)
{
    //here, we log our arguments args.....
    //then, we pass the call to real object _target for a real method call

    result = targetMethod.Invoke(_target, args);

    //here, we log result of the call
    
    return result;
}

So, now we have a mechanism to generically intercept all method calls in one place.

Logging Mechanism

The requirement I had was that the logging of interface IA is done in a separate log, independent from any other logging mechanism in the application. So, I need a new logger in my code. I decided to use NLog [5]. There is no particular reason for that choice, any C# logger will do.

Logging Complex Objects – JSON Serializer

The problem was how to log very complex object objects that are coming as parameters of the methods. They can be a list that contains objects that contain objects etc. I opted for the JSON serializer [7]. The format is well known, and the module is well tested, already implemented, and available.

What to Do With Exceptions?

The problem is what to do when the original method of class A by some chance throws an exception?

protected override object Invoke(MethodInfo targetMethod, object[] args)
{
    //...some code....
    // what if this method throws an exception?
    result = targetMethod.Invoke(_target, args);

    //...some code....
    return result;
}

One of the design principles that we accepted is that our LogginProxy needs to be as transparent to the application as possible. So, we decided to throw also an exception, but first to log everything in the log.

protected override object Invoke(MethodInfo targetMethod, object[] args)
{
    //...some code...
    try
    {
        result = targetMethod.Invoke(_target, args);
    }
    catch (Exception ex)
    {
        //...some code...
    }
    //...some code...
    //...log exception details.....

    throw new Exception(ExceptionMsg);
    return result;
}

Since we are throwing a new Exception, the stack trace will not point anymore to the original code in class A where the exception happened, so we decided to embed the original stack trace in the Exception message.

Final Implementation of LoggingProxyIA

Here is what the final solution of LoggingProxyIA looks like. Code is easily reusable; you just need to replace interface IA with your particular interface, and all will work. Here is the class diagram:

Since most people like code that they can copy-paste, here I will put the whole source code.

 internal interface IA
{
    string Method1(string s1, int[] iArray);
    string Method2(string s1, int[] iArray);
}

internal class A : IA
{
    public string Method1(string s1, int[] iArray)
    {
        // some dummy work
        StringBuilder sb = new StringBuilder();
        sb.Append(s1);
        sb.Append('=');

        for (int i = 0; i < iArray.Length; i++)
        {
            sb.Append(iArray[i].ToString());
            if (i < iArray.Length - 1)
            {
                sb.Append('+');
            }
        }

        Thread.Sleep(10);
        return sb.ToString();
    }

    public string Method2(string s1, int[] iArray)
    {
        //throwing exception to test proxy
        throw new System.IO.FileNotFoundException("Thrown in Method2");
    }
}

internal class LoggingProxy<T> :
        System.Reflection.DispatchProxy where T : class
{
    // static method
    public static T CreateProxy(T target, ILogger logger)
    {
        var proxy = Create<T, LoggingProxy<T>>() as LoggingProxy<T>;  //(555)
        proxy._target = target;
        proxy._logger = logger;
        return proxy as T;
    }

    //instance properties and methods
    private T _target = null;
    private ILogger _logger = null;

    protected override object Invoke(MethodInfo targetMethod, object[] args)
    {
        string methodName = targetMethod.Name;
        string argumentsString = 
            PrepareArgumentsForLogging(args, targetMethod.GetParameters());

        object result = null;
        string ExceptionLogMsg = null;
        string NewExceptionMsg = null;
        Exception exceptionHappaned = null;
        var timer = new Stopwatch();
        timer.Start();
        //------------------------
        try
        {
            result = targetMethod.Invoke(_target, args);
        }
        catch (Exception ex)
        {
            // this exception is thrown by this framework
            // inner exception is original problem
            // we want to preserve original stack trace and message
            exceptionHappaned = ex;
            NewExceptionMsg = ExceptionLogMsg = ex.Message;

            if (ex.InnerException != null)
            {
                ExceptionLogMsg += ";\n " + ex.InnerException.ToString();
                NewExceptionMsg = ex.InnerException.ToString();
                exceptionHappaned = ex.InnerException;
            }
        }
        //------------------------
        timer.Stop();
        TimeSpan timeTaken = timer.Elapsed;
        string timeTakenString = timeTaken.ToString(@"m\:ss\.fff");

        string resultString = PrepareResultForLogging(result);
        string logText = PrepareMethodLog(
            methodName, timeTakenString, argumentsString, 
            resultString, ExceptionLogMsg);
        _logger.Debug(logText);

        if (exceptionHappaned != null)
        {
            //want to crete same Exception type as Inner Exception
            //so we would have transparency when thrown
            //with stack trace from original inner exception
            //in exception message
            //but stack trace will be different since it is 
            //created new exception
            Type exceptionType = exceptionHappaned.GetType();
            Exception newException = (Exception)
                Activator.CreateInstance(
                exceptionType, new object[] { NewExceptionMsg });
            throw newException;
        }

        return result;
    }

    private string PrepareArgumentsForLogging(
         object[] args, ParameterInfo[] parameterInfos)
    {
        StringBuilder sb = new StringBuilder();

        for (int i = 0; i < parameterInfos.Length; i++)
        {
            sb.Append("---Argument ");
            sb.Append(i);
            sb.Append(": Name ");
            sb.Append(parameterInfos[i].Name);
            sb.Append(": Type ");
            sb.Append((args != null && args.Length >= i + 1) ? 
                       args[i]?.GetType().Name : String.Empty);
            sb.Append("-------\n");
            sb.Append(PrepareArgumentForLogging(
                (args != null && args.Length >= i + 1) ? args[i] : null));
            sb.Append("\n");
        }
        return sb.ToString();
    }

    private string PrepareResultForLogging(object arg)
    {
        StringBuilder sb = new StringBuilder();
        sb.Append("---Result ");
        sb.Append(": Type ");
        sb.Append(arg?.GetType().Name);
        sb.Append("-------\n");
        sb.Append(PrepareArgumentForLogging(arg));
        sb.Append("\n");
        return sb.ToString();
    }

    private string PrepareArgumentForLogging(object obj)
    {
        StringBuilder sb = new StringBuilder();
        var indented = Newtonsoft.Json.Formatting.Indented;
        var settings = new JsonSerializerSettings()
        {
            TypeNameHandling = TypeNameHandling.All
        };
        sb.Append(JsonConvert.SerializeObject(obj, indented, settings));
        return sb.ToString();
    }

    private string PrepareMethodLog(
        string methodName, string timeTaken, string arguments, 
        string result, string exceptionMsg)
    {
        StringBuilder sb = new StringBuilder();
        sb.Append($"\n=== Method {methodName} took time {timeTaken} ===\n");
        sb.Append(arguments);
        sb.Append(result);
        if (exceptionMsg != null)
        {
            sb.Append("---Exception -------\n");
            sb.Append(exceptionMsg);
            sb.Append("\n");
        }
        sb.Append(
      "===========================================================================");
        return sb.ToString();
    }
}

internal class LoggingProxyIA : LoggingProxy<IA>
{
}

static void Main(string[] args)
{
    Console.WriteLine("LoggingProxy Test");

    // configuring and creating logger
    var config = new NLog.Config.LoggingConfiguration();
    var logfile = new NLog.Targets.FileTarget("logfile") 
        { FileName = @"C:\Tmp\LoggingProxy.log" };
    config.AddRule(NLog.LogLevel.Debug, NLog.LogLevel.Fatal, logfile);
    NLog.LogManager.Configuration = config;
    ILogger logger = NLog.LogManager.GetCurrentClassLogger();

    //testing class
    IA iA1 = new A();
    iA1.Method1("Test", new int[] { 1, 2, 3 });

    //testing proxy
    IA iA2 = LoggingProxyIA.CreateProxy(new A(), logger);
    iA2.Method1("Test", new int[] { 1, 2, 3 });
    try
    {
        iA2.Method2("Test", new int[] { 1, 2, 3 });
    }
    catch (Exception ex)
    {
        Console.WriteLine($"Exception: {ex.ToString()}");
    }

    NLog.LogManager.Flush();
    Console.ReadLine();

}

Here is what the generated log looks like:

===========================================================================
2022-06-07 21:08:43.7885|DEBUG|_01_LoggingProxy.Program|
=== Method Method1 took time 0:00.021 ===
---Argument 0: Name s1: Type String-------
"Test"
---Argument 1: Name iArray: Type Int32[]-------
{
  "$type": "System.Int32[], System.Private.CoreLib",
  "$values": [
    1,
    2,
    3
  ]
}
---Result : Type String-------
"Test=1+2+3"
===========================================================================
2022-06-07 21:08:43.8130|DEBUG|_01_LoggingProxy.Program|
=== Method Method2 took time 0:00.009 ===
---Argument 0: Name s1: Type String-------
"Test"
---Argument 1: Name iArray: Type Int32[]-------
{
  "$type": "System.Int32[], System.Private.CoreLib",
  "$values": [
    1,
    2,
    3
  ]
}
---Result : Type -------
null
---Exception -------
Exception has been thrown by the target of an invocation.;
 System.IO.FileNotFoundException: Thrown in Method2
   at _01_LoggingProxy.A.Method2(String s1, Int32[] iArray)
===========================================================================

And here is what a deliberately thrown exception trace looks like:

The proxy will rethrow the exception deliberately to be as transparent as possible to the client’s application, just the stack trace will be different, and the original stack trace will be in the Exception message.

Conclusion

LoggingProxy, based on the Proxy Design Patten is a very useful technology. It can give us insight into the sequence of method calls and all data transfers happening on a certain interface. That can be useful for debugging purposes or for the purpose of documenting the protocol of usage of the interface.

In this article, we built a practical reusable LoggingProxy and showed its source code.

References

• [1] https://en.wikipedia.org/wiki/Proxy_pattern
• [2] https://docs.microsoft.com/en-us/dotnet/api/system.reflection.dispatchproxy?view=net-6.0
• [3] https://docs.microsoft.com/en-us/dotnet/api/system.reflection.dispatchproxy.create?view=net-6.0#system-reflection-dispatchproxy-create-2
• [4] https://www.jetbrains.com/decompiler/
• [5] https://nlog-project.org/
• [6] https://docs.microsoft.com/en-us/dotnet/standard/serialization/system-text-json-overview?pivots=dotnet-6-0
• [7] https://www.newtonsoft.com/json

History

• 9^th May, 2022: Initial version