Nlog Callsite is wrong when wrapper is used

Question

I'm using NLog for logging, I use a wrapper to call log methods, my problem is: if I try to print information about the call site (${callsite}), it prints the wrapper method and not the original method that caused the logger to log.

Is there any way to get the original method that called the wrapper method instead?

Answer 1

With modern NLog, this can be achieved entirely in configuration, for any logger that will be called via a wrapper method, even an extension method, using the skipFrame parameter of the callsite layout renderer.

Here is an example of an extension method for including a custom property when desired, which preserves the correct callsite information in the logs:

public static class NLogExtensions
{
    [MethodImpl( MethodImplOptions.NoInlining )]
    public static void Info( this Logger logger, int propertyValue, [StructuredMessageTemplate] string messageFormatString, params object[] messageParameters )
    {
        logger.WithProperty("MyCustomProperty", propertyValue).Info(messageFormatString,messageParameters);
    }
}

In your nlog configuration JSON or the "NLog" section of appsettings.json:

{
    /* ... */
    "targets": {
        "myTarget": {
        /* ... */
        "layout": "${whateverOtherStuffYouNeed}|${event-properties:MyCustomProperty:whenEmpty='-'}|${callsite:skipFrames=1}"
    }
/* ... */
}

That's all there is to it. The magic is all in the skipFrames=1, which tells it to ignore the first frame of the stack, which is what some of these answers are doing manually, but which NLog is capable of doing natively.

If your wrapper is deeper than 1 level of indirection from the actual callsite, just adjust the skipFrames parameter to match how deep it is.

The above sample allows you to call the normal NLog methods, which will behave as normal and output - for the custom property, or call Info with an int parameter before the message, which will cause the custom property to be added before logging the line, and will include its actual value in the log output, allowing you to seamlessly use your extension simply by calling another overload.

You can wrap it however you like - this is just an example of one common use case I've seen around the net and that I have had, myself.

Answer 2

Guys After several days hard work and search.Finally, I just use one simple class built the Nlog Wrapper which can retain the ${callsite} and get the correct logger name when created the instance of Nlog Wrapper. I will put the code as followed with simple comment. As you can see I use Stacktrace to get the right logger name. Use write and writewithex to register the logevnet so that can retain callsite. If you have any questions please let me know.

 public  class NlogWrapper 
    {  
        private  readonly NLog.Logger _logger; //NLog logger

    /// <summary>
    /// This is the construtor, which get the correct logger name when instance created  
    /// </summary>

    public NlogWrapper()
        {
        StackTrace trace = new StackTrace();

        if (trace.FrameCount > 1)
        {
            _logger = LogManager.GetLogger(trace.GetFrame(1).GetMethod().ReflectedType.FullName);
        }
        else //This would go back to the stated problem
        {
            _logger = LogManager.GetCurrentClassLogger();
        }
    }
    /// <summary>
    /// These two method are used to retain the ${callsite} for all the Nlog method  
    /// </summary>
    /// <param name="level">LogLevel.</param>
    ///  <param name="format">Passed message.</param>
    ///  <param name="ex">Exception.</param>
    private void Write(LogLevel level, string format, params object[] args)
    {
        LogEventInfo le = new LogEventInfo(level, _logger.Name, null, format, args);
        _logger.Log(typeof(NlogWrapper), le);
    }
    private void WriteWithEx(LogLevel level, string format,Exception ex, params object[] args)
    {
        LogEventInfo le = new LogEventInfo(level, _logger.Name, null, format, args);
        le.Exception = ex;
        _logger.Log(typeof(NlogWrapper), le);
    }


    #region  Methods
    /// <summary>
    /// This method writes the Debug information to trace file
    /// </summary>
    /// <param name="message">The message.</param>
    public  void Debug(String message)
        {
            if (!_logger.IsDebugEnabled) return;

        Write(LogLevel.Debug, message);
    }  

    public  void Debug(string message, Exception exception, params object[] args)
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Debug, message, exception);
    }

    /// <summary>
    /// This method writes the Information to trace file
    /// </summary>
    /// <param name="message">The message.</param>
    public  void Info(String message)
        {
            if (!_logger.IsInfoEnabled) return;
        Write(LogLevel.Info, message);
    }

    public  void Info(string message, Exception exception, params object[] args) 
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Info, message, exception);
    }
    /// <summary>
    /// This method writes the Warning information to trace file
    /// </summary>
    /// <param name="message">The message.</param>
    public  void Warn(String message)
        {
            if (!_logger.IsWarnEnabled) return;
          Write(LogLevel.Warn, message); 
        }

    public  void Warn(string message, Exception exception, params object[] args)
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Warn, message, exception);
    }

    /// <summary>
    /// This method writes the Error Information to trace file
    /// </summary>
    /// <param name="error">The error.</param>
    /// <param name="exception">The exception.</param>
    //   public static void Error( string message)
    //  {
    //    if (!_logger.IsErrorEnabled) return;
    //  _logger.Error(message);
    //}

    public  void Error(String message) 
    {
        if (!_logger.IsWarnEnabled) return;
        //_logger.Warn(message);
        Write(LogLevel.Error, message);
    }
    public void Error(string message, Exception exception, params object[] args)
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Error, message, exception);
    }  


    /// <summary>
    /// This method writes the Fatal exception information to trace target
    /// </summary>
    /// <param name="message">The message.</param>
    public void Fatal(String message)
        {
            if (!_logger.IsFatalEnabled) return;
         Write(LogLevel.Fatal, message);
    }

    public void Fatal(string message, Exception exception, params object[] args)
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Fatal, message, exception);
    }

    /// <summary>
    /// This method writes the trace information to trace target
    /// </summary>
    /// <param name="message">The message.</param>
    /// 
    public  void Trace(string message, Exception exception, params object[] args)  
    {
        if (!_logger.IsFatalEnabled) return;
        WriteWithEx(LogLevel.Trace, message, exception);
    }
    public  void Trace(String message)
        {
            if (!_logger.IsTraceEnabled) return;
            Write(LogLevel.Trace, message);
    }

        #endregion

    }

Answer 3

You could also add this to your NLogLogger Class and call it in the first line of the Write method.

    protected void GetCurrentClassLogger()
    {
        //This should take you back to the previous frame and context of the Log call
        StackTrace trace = new StackTrace();

        if (trace.FrameCount > 1)
        {
            logger = LogManager.GetLogger(trace.GetFrame(1).GetMethod().ReflectedType.FullName);
        }
        else //This would go back to the stated problem
        {
            logger = LogManager.GetCurrentClassLogger();
        }
    }


    private void Write(LogLevel level, string format, params object[] args)
    {
        //added code
        GetCurrentClassLogger();

        LogEventInfo le = new LogEventInfo(level, logger.Name, null, format, args);
        logger.Log(typeof(NLogLogger), le);
    }

Answer 4

See my answer to this question:

Problem matching specific NLog logger name

I have copied the example code (for an abbreviated NLog wrapper) from that answer here to save some trouble:

  class NLogLogger : ILogger
  {
    private NLog.Logger logger;

    //The Type that is passed in is ultimately the type of the current object that
    //Ninject is creating.  In the case of my example, it is Class1 and Class1 is
    //dependent on ILogger.
    public NLogLogger(Type t)
    {
      logger = NLog.LogManager.GetLogger(t.FullName);
    }

    //Trace, Warn, Error, Fatal eliminated for brevity

    public bool IsInfoEnabled
    {
      get { return logger.IsInfoEnabled; }
    }

    public bool IsDebugEnabled
    {
      get { return logger.IsDebugEnabled; }
    }

    public void Info(string format, params object [] args)
    {
      if (logger.IsInfoEnabled)
      {
        Write(LogLevel.Info, format, args);
      }
    }

    public void Debug(string format, params object [] args)
    {
      if (logger.IsDebugEnabled)
      {
        Write(LogLevel.Debug, format, args);
      }
    }

    private void Write(LogLevel level, string format, params object [] args)
    {
      LogEventInfo le = new LogEventInfo(level, logger.Name, null, format, args);
      logger.Log(typeof(NLogLogger), le);
    }
  }

Note that this answer was given in the context of NInject. The same principal applies to wrapping NLog even if you are not using NInject. The key is communicating to NLog the type of your wrapper.

This is on example of how to write an NLog wrapper correctly (i.e. to maintain call site info). The key is in the Write method. Notice how it uses NLog's Log method. Notice also that is passes the type of the wrapper class as the first parameter. NLog uses the type information to navigate up the call stack. As soon as it sees a method whose DeclaringType is the passed-in type (i.e. the type of the wrapper), it knows that the next frame up the stack is the calling method.

Also see this link (to NLog's source repository) for two more examples of "extending" Logger. One by wrapping, one by inheriting:

https://github.com/jkowalski/NLog/tree/master/examples/ExtendingLoggers

I am not 100% sure, but I think that you cannot simply wrap NLog and delegate the Info, Debug, Warn, etc method to NLog like this:

class MyNLogWrapper
{
  private readonly Logger logger = LogManager.GetCurrentClassLogger();

  public void Info(string msg)
  {
    logger.Info(msg);
  }
}

You need a way to tell NLog the type of your wrapper and I think that you can only do that by calling NLog via the Logger.Log method (overloaded).

If this is not useful enough, post your wrapper for more help.