WCF 日志记录行为的错误 NLog 调用站点

Question

我正在编写类似this blog by Pieter de Rycke 的日志记录行为，但针对的是 NLog。我想出了这段代码：

public class NLogLogger : IParameterInspector
{
    private void Log(Type instanceType, string operationName, string msg)
    {
        NLog.Logger logger = LogManager.GetLogger(
            instanceType.FullName, instanceType);
        logger.Info(msg, instanceType);
    }

    public object BeforeCall(string operationName, object[] inputs)
    {
        // Retrieve the service instance type for the logger then log the call.
        OperationContext operationContext = OperationContext.Current;
        Type instanceType = operationContext.InstanceContext
            .GetServiceInstance().GetType();
        Log(instanceType, operationName, "BeforeCall");

        return instanceType;
    }

    public void AfterCall(
        string operationName, object[] outputs,
        object returnValue, object correlationState
    )
    {
        if (correlationState is Type)
            Log(correlationState as Type, operationName, "AfterCall");
    }
}

日志记录行为正常。我使用 Pieter 描述的属性将其注入到服务 Example.MyService 中。我在 NLog 目标中有这个布局：

${longdate} ${callsite} ${level:uppercase=true} ${message}

但是GetContacts 操作的调用点是错误的：

2013-07-11 13:32:53.1379 Common.NLogLogger.Log INFO BeforeCall
2013-07-11 13:32:53.7121 Common.NLogLogger.Log INFO AfterCall

正确的是：

2013-07-11 13:32:53.1379 Example.MyService.GetContacts INFO BeforeCall
2013-07-11 13:32:53.7121 Example.MyService.GetContacts INFO AfterCall

我尝试了什么？

NLog 为记录包装器或外观提供了调用站点的特殊处理，如 StackOverflow answer 中所述：将调用站点的类传递给记录方法。

事实上，我在上面的Log() 方法中使用logger.Info(msg, instanceType) 做到了这一点。但是，这不起作用，因为当行为的 BeforeCall() 方法正在运行时，调用站点尚未在堆栈跟踪中。 WCF 甚至还没有开始运行操作。 NLog 在堆栈跟踪中找不到调用点，并且无法解开堆栈跟踪。

如何伪造呼叫站点？或者如何显示日志记录行为的“正确”调用站点？

Answer 1

更新：

感谢您的澄清，我更好地理解了您要做什么。您希望从 IParameterInspector 实现记录的消息反映“Example.MyService.GetContacts”的调用站点，其中 Example.MyService 是您的服务（由 instanceType 参数指示），“GetContacts”是操作。您可以手动合成呼叫站点信息。您仍将使用 NLog 的 Logger.Log 方法，并且仍将创建 LogEventInfo 对象。此外，您可以将“类”和“方法”存储在 LogEventInfo.Properties 对象中。与其根据 instanceType（即服务）检索记录器（来自 LogManager），不如根据参数检查器的类型（在您的情况下为 NLogLogger）检索记录器。最后，您可以在 NLog.config 中添加一个附加规则（并将其应用于 NLogLogger 类型），以便该规则具有不同的日志记录格式。您将手动将一个字段添加到包含调用站点信息（存储在 LogEventInfo.Properties 集合中）的日志格式，该字段与您的其他日志记录规则配置中的“真实”调用站点 LayoutRenderer 位置相同。

接下来我将发布一个新版本的 NLogLogger 实现，它执行我上面描述的操作。

public class NLogLogger : IParameterInspector
{
    private static readonly NLog.Logger logger = LogManager.GetCurrentClassLogger();

    private void Log(Type instanceType, string operationName, string msg)
    {
        NLog.Logger serviceLogger = LogManager.GetLogger(
            instanceType.FullName, instanceType);

        //Create LogEventInfo with the Logger.Name from the logger associated with the service
        LogEventInfo le = new LogEventInfo(LogLevel.Info, serviceLogger.Name, msg);
        le.Properties.Add("fakecallsite", string.Format("{0}.{1}",instanceType.ToString(),operationName);

        //Log the message using the parameter inspector's logger.
        logger.Log(typeof(NLogLogger), le);
    }

    public object BeforeCall(string operationName, object[] inputs)
    {
        // Retrieve the service instance type for the logger then log the call.
        OperationContext operationContext = OperationContext.Current;
        Type instanceType = operationContext.InstanceContext
            .GetServiceInstance().GetType();
        Log(instanceType, operationName, "BeforeCall");

        return instanceType;
    }

    public void AfterCall(
        string operationName, object[] outputs,
        object returnValue, object correlationState
    )
    {
        if (correlationState is Type)
            Log(correlationState, operationName, "AfterCall");
    }
}

你的 NLog.config 会有类似这样的规则。一条规则专门针对您的 NLogLogger 参数检查器。它记录到“f1”并且是“最终”规则，这意味着来自参数检查器的记录消息不会被任何其他规则记录。另一条规则适用于所有其他记录器。每个记录到不同的文件目标，但两个文件目标都写入同一个文件（我认为这可行）。关键是每个文件都有自己的布局。

<logger name="Your.Full.NameSpace.NLogLogger" minlevel="*" writeTo="f1" final="true" /> 
<logger name="*" minlevel="*" writeTo="f2" /> 

您的目标和布局看起来像这样。我们定义了一个变量，其值为 EventPropertiesLayoutRenderer 的值，也就是我们存储在 LogEventInfo.Properties["fakecallsite"] 中的假调用站点。

  <variable name="fakecallsite" value="${event-properties:fakecallsite}"/>
  <variable name="f1layout" value="${longdate} | ${level} | ${logger} | ${fakecallsite} | ${message}"/>
  <variable name="f2layout" value="${longdate} | ${level} | ${logger} | ${callsite} | ${message}"/>
  <targets>
    <target name="f1" xsi:type="File" layout="${f1layout}" fileName="${basedir}/${shortdate}.log" />
    <target name="f2" xsi:type="File" layout="${f2layout}" fileName="${basedir}/${shortdate}.log"        />
  </targets>

请注意，我没有尝试过这个，但我认为它应该可以工作（或者应该足够接近你可以让它工作）。一个限制是，由于我们正在计算假呼叫站点，因此我们不能使用真正的呼叫站点 LayoutRenderer 来操纵输出中 fakecallsite 字段的内容。如果这很重要，可以通过分别存储类和方法（在 LogEventInfo.Properties 中）然后在 NLog.config 中设置“fakecallsite”变量来包含类、方法或两者来模拟它。

结束更新

您的包装器应该使用 Log 方法。此外，您传递给 NLog Logger.Log 方法的类型应该是 NLog Logger 包装器的类型，而不是服务实例类型的类型。您仍然可以使用服务实例的类型来检索正确的 Logger 实例。它应该看起来像这样：

public class NLogLogger : IParameterInspector
{
    private void Log(Type instanceType, string operationName, string msg)
    {
        NLog.Logger logger = LogManager.GetLogger(
            instanceType.FullName, instanceType);

        //This is the key to preserving the call site in a wrapper.  Create a LogEventInfo
        //then use NLog's Logger.Log method to log the message, passing the type of your 
        //wrapper as the first argument.

        LogEventInfo le = new LogEventInfo(LogLevel.Info, logger.Name, msg);
        logger.Log(typeof(NLogLogger), le);
    }

    public object BeforeCall(string operationName, object[] inputs)
    {
        // Retrieve the service instance type for the logger then log the call.
        OperationContext operationContext = OperationContext.Current;
        Type instanceType = operationContext.InstanceContext
            .GetServiceInstance().GetType();
        Log(instanceType, operationName, "BeforeCall");

        return instanceType;
    }

    public void AfterCall(
        string operationName, object[] outputs,
        object returnValue, object correlationState
    )
    {
        if (correlationState is Type)
            Log(correlationState, operationName, "AfterCall");
    }
}