65.9K
CodeProject 正在变化。 阅读更多。
Home

C# 中的日志代理

Mark Pelf
starIconstarIconstarIconstarIconstarIcon

5.00/5 (13投票s)

2022年5月9日

MIT

6分钟阅读

viewsIcon

17168

downloadIcon

240

在本文中，我们将构建一个实用的、可重用的 C# 日志代理。

用于记录日志的接口使用，以记录其文档

这一切都始于一项实际任务。项目负责人找到我，给我提出了一个实际问题。在我们的一款银行应用程序中，有一个名为 IA 的接口，它被一个名为 A 的特定通信模块实现。类 A 使用特定的银行协议进行非常复杂的通信。他们正在考虑通过用新的模块 A2 替换通信模块 A 来为新客户采用该应用程序。

问题是，关于接口 IA 唯一有效的文档就是代码本身。其他文档已过时，并且实现模块 A 的人员已离职。

因此，我们需要记录接口 IA。我被要求记录接口 IA 上的所有通信，包括所有传入和传出的参数，带有时间戳，以及正确的方法调用顺序，并将 Log 作为接口 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. 使用反射技术来通用地拦截方法调用

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

拦截方法调用

因此，我需要一种拦截方法调用的机制。幸运的是，这样的库已经存在，它叫做 System.Reflection.DispatchProxy [2]。它提供了一个实例化代理对象并处理其方法调度的机制。它有一个非常简单的 public 接口

public abstract class DispatchProxy
{
    protected DispatchProxy();

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

此类设计用于由你的实际代理实现继承，并具有受保护的构造函数。让我们看一下重要的方法。

Create 方法

Create 是创建代理对象的地方。但方法签名有点误导。如果我们看方法签名

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

它表明它返回类型为 T 的对象。但事实是返回的对象实现了接口 T 并扩展了 TProxy。因此，可以将返回的对象转换为 TProxy 类型，这从方法签名中并不明显。我将在代码的 (555) 位置使用这个特性。

我们如何知道我说的是实话？首先，如果你仔细阅读文档 [3]，它确实在某个地方提到了这一点。其次，你可以使用像 dotPeek [4] 这样的反编译器来查看该类的源代码。通过其神奇的工作，它甚至会提供代码中的注释。这是我用 dotPeek 找到的

你可以浏览反编译的代码来验证它是否真的按照注释所说的在做。

查看 dotPeek 中 Create 方法进行的检查也很有趣，这样你就可以知道提供的参数 T 和 TProxy 的限制。

总而言之，Create 方法将创建我们需要的 Proxy 对象，并且结果对象同时是 T 和 TProxy 类型。

Invoke 方法

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 序列化器

问题是如何记录作为方法参数传入的非常复杂的对象。它们可以是一个包含其他对象的列表，依此类推。我选择了 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 的最终实现

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

}

生成的日志看起来是这样的

===========================================================================
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 基于代理设计模式，是一项非常有用的技术。它可以让我们深入了解特定接口上方法调用的顺序以及发生的所有数据传输。这对于调试目的或记录接口使用协议的目的都很有用。

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

参考文献

历史

  • 2022 年 5 月 9 日：初始版本
© . All rights reserved.