callsite is lost through NLogFacade

Apr 21, 2010 at 4:54 PM
Edited Apr 21, 2010 at 4:59 PM

Greetz.

First of all, thanks for the great work done in SFL. It was exactly what I was looking for.
Im starting to use it but I found a major problem.

The situation is as follows:
I want to use NLog as my Logging framework, and to be able to print the callsite of a Log event.

Currently, a LOG event is printed out to the console as this:

2010-04-21 17:43:37.1485 SLF.NLogFacade.NLogLogger.Log -Info- Is logging working?
at 21-04-2010 17:43:37

and not as:

2010-04-21 17:43:37.1485 My.Namespace.MyClass -Info- Is logging working?
at 21-04-2010 17:43:37

As you can see, I loose the callsite, not being able to locate where the LOG came from.

Here's my startup configuration for NLog:

  <nlog
      xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"    
      >
    <targets>
      <target name="f1" xsi:type="File" fileName="c:/file1.txt"/>
      <target name="c" xsi:type="Console" layout="${longdate} ${callsite} ${level} ${message}"/>
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" maxlevel="Error" writeTo="c" />
      <logger name="*" minlevel="Info" maxlevel="Error" writeTo="c" />
      <logger name="*" minlevel="Info" maxlevel="Error" writeTo="f1" />
    </rules>
  </nlog>

Is this a problem of the facade that is not telling NLog properly where the LOG event was created or am I doing something wrong?

Thanks in advance,
M.

Coordinator
May 1, 2010 at 6:28 AM

Hi,

Sorry for the slow reply - it has been a busy week, I got stuck in Eurpose because of the Icelandic volcano then spent a week catching up on things!

Yes, I am aware of this issue. I presume the NLog framework determines the callsite by inspecting the stack, it probably expects the callsite to be a fixed number of frames down the stack. SLF will add extra calls to the stack.

I think Daniel Vaughen mentioned that he had fixed this problem in CLOG, his logging framework. I intend to have a look into this shortly.

Regards, Colin E.

May 1, 2010 at 9:11 AM

Hi Colin,

Thanks for the prompt reply and for looking into it.

Regards,

Mário F. Pinhal

Coordinator
May 4, 2010 at 1:43 PM
Edited May 4, 2010 at 1:45 PM
Hi Mario, I have committed a fix for NLog, the SLF framework classes will no longer appear in your NLog callsite or stacktrace information. See the following changeset: http://slf.codeplex.com/SourceControl/changeset/changes/65945 I am trying to work out a solution for log4net, which is not so easy :-( Once this is done, we will probably release the next SLF version. Regards, Colin E.
May 4, 2010 at 11:44 PM

Thanks Colin :)

I'm looking forward to the next release then, and I'll look into it to try to use this revision/changeset perhaps in our test environment.
I'll let you know if I found any related issues.

Regards,

Mario

Coordinator
May 5, 2010 at 7:21 AM

Hi Mario,

No problem - if you have any more feedback, let me know. I think we will release a new version quite soon. We do not have many pending new features (we are keeping SLF simple!), so I will probably bundle this with just one or two other changes shortly.

Regards, Colin E.

May 27, 2010 at 1:43 PM
Hey Colin, Any Idea about when will a new version be released? Regards, Mário
Aug 20, 2010 at 7:52 PM
Edited Sep 10, 2010 at 6:27 PM

EDIT - You can probably skip to the last paragraph.  As I was typing in the rest of it, I came across some useful info about how other NLog and log4net wrappers are able to preserve the calling location.  The rest of the stuff that I typed might be of use to someone, but probably not for this problem.

 

You might already know this, but the log4net logger supports an ILogger interface (note that this is NOT the same as the log4net ILog interface).  According to the documentation, ILogger.Log is the most generic way to log a message.  It has two overloads, one of which takes a LoggerEvent class.  LoggerEvent appears to be similar to NLog's LogEvent (which you apparently used to preserve the call site info for your NLog wrapper).  Maybe you could use a similar approach to preserve log4net's call site info as you used to preserve NLog's.  One field in LoggerEvent is LocationInfo.  It looks like LocationInfo can get the location info automatically (which won't help if it is called from within SLF) OR it also has a constructor that accepts the class name, method name, filename, and line number which might be easier to obtain (class name and method name, anyway).

Another idea, maybe not a good one, is to use the approach that is used within the Logging Application Block.

Here is what LAB does in its logger (or did in the version that is available on koders.com):

private string GetCallingMethod()
        {
            string methodName = string.Empty;
            StackTrace trace = new StackTrace(true);
            foreach (StackFrame frame in trace.GetFrames())
            {
                // find the first method that isn't from this class
                if (!frame.GetMethod().ReflectedType.Equals(typeof(EntLibLogger)) &&
                    !frame.GetMethod().ReflectedType.Equals(typeof(ExceptionManager)))
                {
                    methodName = string.Format("{0} {1}:{2}",
                        frame.GetMethod().DeclaringType.ToString(),
                        frame.GetMethod().ToString(),
                        frame.GetFileLineNumber());
                    break;
                }
            }
            return methodName;
        }

Anyway, this class walks the stack up until the type of the MethodBase is not one of several Enterprise Library types. 

Here is some experimental code that I wrote trying to mimic what is going on in LAB.  I think that I got the "IsAssignableFrom" bit from StackOverflow, as I don't recall that LAB did this exactly the same way:

 

    internal string GetCallingMethodName()
    {
      string result = "unknown";
      StackTrace trace = new StackTrace(false);
      for (int i = 0; i < trace.FrameCount; i++)
      {
        StackFrame frame = trace.GetFrame(i);
        MethodBase method = frame.GetMethod();
        Type dt = method.DeclaringType;
        if (!typeof(ILogger).IsAssignableFrom(dt) && method.DeclaringType.Namespace != "DiagnosticsLibrary")
        {
          result = string.Concat(method.DeclaringType.FullName, ".", method.Name);
          break;
        }
      }
      return result;
    }

 

The idea is to walk the stack up until you hit a MethodBase that does not support ILogger and the MethodBase's namespace is not the "logging" namespace.  In my case, this code was in a class that implements ILogger.  If I had put the code in some other part of the logging infrastructure, then the IsAssignableFrom check is probably not good.

Obviously this is expensive to do on every logging call.  Part of the problem is that, by default, log4net and NLog don't have to do this unless that is an element in the formatting string that specifies that the call site should be logged.  So, at the time the message is logged (from application code directly to log4net or NLog), no extra cost is paid.  The cost does not come until the message is actually formatted by log4net or NLog and written out.  If the wrapper gets the call site info (as was done in the NLog wrapper/facade) then the cost of getting the information is paid during every logging call, whether or not the underlying logger's formatting string is going to use it.  I guess that there is not much that can be done since it is probably difficult/impossible to tell when/if an underlying logger is going to need to call site info.

Having said all of that, see the answer by flanders in this post from StackOverflow for another way to get the calling method/class from an arbitrary depth in the calling stack:

http://stackoverflow.com/questions/171970/how-can-i-find-the-method-that-called-the-current-method

One way to save the cost of determining the call site info could be to have a configuration parameter in the "logging factory" config section (where you can specify the log4net or NLog facades) that says whether or not to get the call site info.  So, if someone is using log4net and chooses not to configure call site info in any formatting strings, then he/she could turn the option off in the log4net facade config section.  If the "GetCallSiteInfo" parameter is "true", then get the info, populate the LoggingEvent/LogEvent class/structure, and use the underlying logging platform's generic "Log" method.  If "false", could still use the LoggingEvent/LogEvent and the generic "Log" method, but populate method and class with something like "[SLF CALL SITE LOGGING NOT CONFIGURED]" (or similar).  Putting something like that for the method/class info would make it a bit more obvious if there was a conflict between asking for the call site info in log4net/NLog and NOT asking for it in SLF.  Alternatively, SLF could log an informational message in its internal log about whether or not the call site parameter was set.  In the actually logging call (SLF's call to log4net/NLog to log), if call site info is not specified, you might just want to use the "normal" way of calling log4net/NLog (logger.Info(blah blah) rather than logger.Log(new LogEvent(blah blah blah).

After typing all of that about getting the calling method info by walking the stack, I just looked at log4net some more and it looks like, maybe, the ILogger.Log function (remember, ILogger not ILog) supports a similar concept to NLog's Logger.Log( ... ), which you used to preserve call site info for NLog.  Log4net's ILogger.Log call takes a Type parameter that, according to the docs, means this: "The declaring type of the method that is the stack boundary into the logging system for this call".  Maybe it functions the same was as the Type passed to NLog's Logger.Log call?  Maybe you have already looked at this and determined that it doesn't work the same way.  Anyway, just thought I would pass it along.

Anyway. maybe you will find some of this useful, maybe not.  I don't know yet if our project will use SLF, but I certainly think that it looks interesting.

Sep 10, 2010 at 6:19 PM

Building on my last comment, here is some code from Common.Logging that I think is showing the correct technique for preserving the code location.  Note that declaringType is stored in the wrapping logger (in this case Common.Logging's Log4netLogger) and it is the type of their Log4netLogger (as compared to the use of the logger's base class that is used to make NLog's code location work correctly).

        /// <summary>
        /// Sends the message to the underlying log4net system.
        /// </summary>
        /// <param name="logLevel">the level of this log event.</param>
        /// <param name="message">the message to log</param>
        /// <param name="exception">the exception to log (may be null)</param>
        protected override void WriteInternal(LogLevel logLevel, object message, Exception exception)
        {
            Level level = GetLevel(logLevel);
            _logger.Log(declaringType, level, message, exception);
        }

Feb 16, 2011 at 3:11 AM

Have this been fixed for NLog? Instead of importing the NLogFacade dll, I copied the 2 files into my project. Would this prevent callsite from working?

I set up logger in my global.ascx file as follows:

  //Setup logger
  LoggerService.FactoryResolver = new SimpleFactoryResolver(new NLogLoggerFactory());

Later down in my app, I log like this:
ILogger logger = LoggerService.GetLogger();
logger.Error("Exception: {0}", ex.Source);

My NLog.onfig:
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <targets>
    <target name="file" xsi:type="AsyncWrapper" queueLimit="5000" overflowAction="Discard">
      <target name="FileError"
            xsi:type="File"
            fileName="${basedir}/App_Data/Logs/errors.txt"
            archiveFileName="${basedir}/App_Data/Archives/log.{#####}.txt"
            archiveAboveSize="10240"
            archiveNumbering="Sequence"
            concurrentWrites="true"
            keepFileOpen="false"
            encoding="iso-8859-2"
            layout="${longdate}|${callsite:className=true:fileName=false:includeSourcePath=false:methodName=true}|${message}"/>
      <target name="FileInfo" xsi:type="File" fileName="${basedir}/App_Data/Logs/info.txt"/>
    </target>
  </targets>
  <rules>
    <logger name="*" level="Error" writeTo="FileError"/>
    <logger name="*" level="Info" writeTo="FileInfo"/>
  </rules>
</nlog>