C#中的日志代理

目录

记录接口使用以记录它

代理设计模式

拦截方法调用

创建方法

调用方法

日志记录机制

日志记录复杂对象——JSON序列化器

如何处理异常？

LoggingProxyIA的最终实现

结论

参考

• 下载源代码

这一切都始于一项实际任务。项目领导向我提出了一个实际问题。在我们的一个银行应用程序中，我们有一个由某个通信模块A实现的某个地方接口IA。类A正在通过特定的银行协议进行非常复杂的通信。他们正在考虑通过用新模块A2替换通信模块A来为新客户采用该应用程序。

问题是接口IA存在的唯一有效文档是代码本身。其他文档已过时，实施模块A的人员不再在公司工作。

所以，我们需要日志记录interface IA。我被要求日志记录interface IA上的所有通信，所有传入和传出参数，时间戳，正确的方法调用顺序，Log将成为interface IA的文档。

我开始浏览IA和A的代码。IA很复杂，有许多带有复杂参数的方法，比如包含其他对象的对象列表。很明显，像将日志代码插入类A这样的幼稚方法并不是一个好主意。我的担忧是：

1. 不想干扰运行良好的复杂代码；
2. 日志记录完成后，所有日志记录代码都需要暂停，但如果再次需要，则可以激活；
3. 我会在多个地方/方法中插入几乎相同类型的日志记录代码，如果可以集中的话会更好。

因此，我决定通过构建日志代理来解决问题。

对于那些不熟悉代理设计模式 [1] 的人，我将简要介绍一下这个想法。所以，我们想替换这样的情况：

有了这样的新设计：

目的是构建LoggingProxyIA（实现接口IA）将拦截对类A的所有调用，将它们转发给类A，同时将所有输入和输出记录到类A的任何方法。LoggingProxyIA尽可能透明是很重要的，这样它就不会以任何方式干扰程序逻辑。应用程序与接口IA对话并且不知道它是否与LoggingProxyIA或类A对话。一旦日志记录完成，LoggingProxyIA将被删除，应用程序将再次直接与A对象对话。由于LoggingProxyIA类保留在源代码中，因此在任何时间点都可以再次激活日志记录。

拦截日志类LoggingProxyIA有两种方式：

1. 在LoggingProxyIA中手动实现IA的每种方法，并记录和转发调用给A；
2. 使用反射技术一般拦截方法调用

显然，方法2)更好，因为我们将只在一个地方实现我们的日志记录并且将创建可重用的代码。

所以，我需要一种机制来拦截方法调用。幸运的是，这样的库已经存在，它被称为System.Reflection.DispatchProxy[2]。它提供了一种用于实例化代理对象和处理它们的方法分派的机制。它有一个非常简单的public接口：

public abstract class DispatchProxy
{
    protected DispatchProxy();

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

此类旨在由您的真实代理实现继承，并具有受保护的构造函数。让我们回顾一下重要的方法。

Create是完成创建代理对象的艰苦工作的地方。但是方法签名有点误导。如果我们查看方法签名：

public static T Create() where TProxy : DispatchProxy; 

它说它返回type T的对象。但事实是返回的对象实现了接口T和扩展TProxy。因此，可以将返回的对象强制转换为TProxy类型，这从方法签名中根本不明显。我将在位置(555)的代码中使用该功能。

我们怎么知道我说的是真话？首先，如果您仔细阅读文档[3]，它确实在一处提到了它。其次，您可以使用像dotPeek [4]这样的反编译器来查看该类的源代码。凭借其神奇的工作，它甚至可以为您提供代码中的注释。这是我在dotPeek中发现的：

您可以浏览反编译的代码以验证它是否确实按照注释所说的那样进行。

使用dotPeek查看正在执行哪种检查Create方法也很有趣，以便您了解提供的参数T和TProxy。

底线是Create方法将为我们创建一个我们需要的Proxy对象，并且生成的对象既是类型T又是TProxy。

Invoke方法是我们拦截发生的地方，也是使用这个类System.Reflection.DispatchProxy的主要目的。这是它的签名：

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

在您的代理实现中，我们需要覆盖此方法并进行日志记录。在下面的代码段中，我们概述了原理：

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;
}

所以，现在我们有了一种机制，可以在一个地方通用地拦截所有方法调用。

我的要求是接口IA的日志记录在一个单独的日志中完成，独立于应用程序中的任何其他日志记录机制。所以，我的代码中需要一个新的记录器。我决定使用NLog[5]。这种选择没有特别的原因，任何C#日志记录器都可以。

问题是如何记录作为方法参数出现的非常复杂的对象对象。它们可以是包含对象的列表，这些对象包含对象等等。我选择了JSON序列化程序[7]。该格式是众所周知的，并且该模块经过了良好的测试，已经实现并且可用。

问题是当类A的原始方法偶然抛出异常时该怎么办？

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;
}

我们接受的设计原则之一是我们LogginProxy需要对应用程序尽可能透明。因此，我们决定也抛出一个异常，但首先要在日志中记录所有内容。

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;
}

由于我们抛出一个new Exception，堆栈跟踪将不再指向发生异常的类A中的原始代码，因此我们决定将原始堆栈跟踪嵌入到Exception消息中。

这是LoggingProxyIA最终解决方案的样子。代码易于重用；你只需要用你的特定接口替换接口IA，一切都会奏效。这是类图：

由于大多数人都喜欢可以复制粘贴的代码，所以我将把整个源代码放在这里。

 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 :
        System.Reflection.DispatchProxy where T : class
{
    // static method
    public static T CreateProxy(T target, ILogger logger)
    {
        var proxy = Create() as LoggingProxy;  //(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
{
}

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();

}

以下是生成的日志的样子：

===========================================================================
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)
===========================================================================

这是故意抛出的异常跟踪的样子：

代理会故意重新抛出异常，以尽可能对客户端的应用程序透明，只是堆栈跟踪会有所不同，原始堆栈跟踪会在Exception消息中。

LoggingProxy，基于Proxy Design Patten是一项非常有用的技术。它可以让我们深入了解方法调用的顺序以及发生在某个接口上的所有数据传输。这对于调试目的或记录接口使用协议的目的可能很有用。

在本文中，我们构建了一个实用的可重用LoggingProxy并展示了它的源代码。

• [1] https://en.wikipedia.org/wiki/Proxy_pattern
• [2] DispatchProxy Class (System.Reflection) | Microsoft Learn
• [3] DispatchProxy.Create
• [4] dotPeek: Free .NET Decompiler & Assembly Browser by JetBrains
• [5] NLog
• [6] Serialize and deserialize JSON using C# - .NET | Microsoft Learn
• [7] Json.NET - Newtonsoft

https://www.codeproject.com/Articles/5331568/Logging-Proxy-in-Csharp