tags:

views:

51

answers:

1

I have two rules configured in NLog.config:

<logger name="Model" level="Info" writeTo="modelLog" final="true" />
<logger name="*" minlevel="Debug" writeTo="logFile" />

I am trying to write to the first one, using the following code:

LogEventInfo eventInfo = new LogEventInfo();
eventInfo.Level = LogLevel.Info;
eventInfo.LoggerName = "Model";
eventInfo.TimeStamp = DateTime.Now;
logger.Log(eventInfo);

But it keeps falling through to the second rule. I would have thought eventInfo.LoggerName = "Model"; would have sent it straight to the first rule?

+2  A: 

Not at computer now so can't try your case, but I have a couple of questions.

  1. Can you try using the "regular" logging functions (Info, Debug) and see if that works ad expected?

  2. How did you resolve your logger? That is. What is "logger's" name?

If the actual logger's name is not "Model" my guess is that it won't meet the "Model" condition, even though you are passing "Model" in the Name field of the LogEventInfo.

[EDIT] Here is an abbreviated example of a better NLog logger wrapper that could be used in the Ninject Logging Extension. This wrapper delegates logging calls to the underlying NLog logger in a way that preserves the call site information (class and method where logging request originated).

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

Obviously this example does not deal with exceptions. However, I think that it illustrates the correct way to wrap NLog. It would be easy enough to implement the full Ninject Logging Extension ILogger interface, delegating each Info, Debug, Warn, etc call to a central Write method that would create the LogEventInfo class and then log it using the underlying NLog logger instance, passing in the type of the wrapping logger (typeof(NLogLogger) in my example). Passing the type of the wrapping logger is critical for maintaining call site info for your logging calls from your application code.

Based on NLog wrapper found in the Ninject Logging Extensions git repository.

More about dependency injection and named loggers (like NLog and log4net).

See my answer here for more about problems with naive logger wrappers.

wageoghe
In my `logFile` target, I'm using the layout `${longdate} ${logger} ${message}`.Using logger.Info("Message"), I get the result `2010-10-17 12:43:59.2080 G6.Infrastructure.Logging.NLogLogger Message`, as I'm using DI to inject my customized logger everwhere.If I use the custom eventInfo as in my question, I get `2010-10-17 12:43:59.2080 Model Message`, so it appears the name is getting modified correctly, just the rules aren't hitting it.
mattdwen
I think the problem is that the name of the actual logger being used is the name that must match the logger name in the config file NOT the name passed in via the LogEventInfo. In effect, you are using a single logger in your application, G6.Infrastructure.Logging.NLogLogger. This is common problem when injecting NLog or log4net loggers. Not at computer right now so it is hard for to find, and add, good links but there are some here at SO about this dilemma.
wageoghe
When you wrap NLog or log4net and expose a single logger instance, you have only a single logger that you can control via the config file. Having a single logger also means that you have only a single log level. You might be able to get around the single level problem by logging via LogEventInfo class, but I don't think the logger name in LogEventInfo is compared against the logger names in the config file. Whether something gets logged or not depends on the name of the actual logger being used to log.
wageoghe
Some DI/IoC frameworks can inject NLog or log4et loggers "correctly" by actually requesting the logger instance based on the type of the class being resolved. I can dig up more info (from here on SO) when I am not posting from my iPhone.
wageoghe
Look in my profile for my question about "Dependency Injection and Named Loggers" and also for some of my answers to posts tagged NLog and you might find some info about the pitfalls of injecting loggers that depend on being "named" correctly.
wageoghe
What DI/IoC framework are you using?
wageoghe
Ninject. Seems all the built in logging modules have been removed with v2.
mattdwen
I was using `var logger = LogManager.GetCurrentClassLogger();`.I've just added a second logger, `var modelLogger = LogManager.GetLogger("Model");` to the class and I'm using that. My misunderstanding of what 'name' matches.It's probably more of a work around than a solution, but it works
mattdwen
Can you write your own "resolver" for Ninject? If yes, do you know if, during the "resolve" phase of an object you have access to the type of object being created. For example, if Class1 is dependent on ILogger, then, when Ninject is building Class1, then Ninject needs to know what object to use to provide the ILogger implementation. If you can write your own resolver (for ILogger) AND if your resolver knows that Class1's dependencies are being resolved, then you can use that type (Class1) to get the class-specific ILogger for Class1.
wageoghe
Note that there is logging extension for Ninject here: http://github.com/ninject/ninject.extensions.logging From looking at it briefly it looks like it's intent is to return a logger as I described earlier. That is, using my Class1 example ... When Class1's ILogger dependency is resolved you will get a logger as if you requested it like this: Logger logger = NLog.GetLogger(typeof(Class1)); that is probably exactly what you want. I am done for the night. Too much iPhone typing not good. Will check back tomorrow. Hope I helped.
wageoghe
One more note. The Ninject logging extension project's NLog imementation is not as good as it could be. If used as-is, you will not be able to get the correct call site info (class ans
wageoghe
One more note. The Ninject logging extension project's NLog imementation is not as good as it could be. If used as-is, you will not be able to get the correct call site info (class and method)of the caller of the logging function. To get the call site info to work correctly for a wrapped or subclassed logger requires a couple of specific steps. See NLog git repository - either Examples or Extensions - for examples of how to wrap or subclass correctly.
wageoghe
Examples/ExtendingLoggers. Instead of using Info, Warn, Error, etc funcs, the NLogLogger should be creating LogEventInfo, populating it with level, logger name, msg, etc then calling Log(typeof(NLogLogger), logEventInfo). The type param is the secret to preserving call site info.
wageoghe