Add variables as prefix to all nLog messages

Question

I am using Nlog to log my Ninjatrader Strategies. I want to be able to add the strategy id as prefix to all my nLog messages so that I can filter the entries related to each account on the strategy separately.

 fileTarget.Layout =  "${longdate} ${callsite} ${level} ${event-context:item=MyValue}  ${message}";`

My current layout is as above. I tried to use event-context:item but dunno how to print the context item for all messages.

I tried as follows

Logger log = LogManager.GetCurrentClassLogger();
LogEventInfo theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name);   
logger.Log(theEvent);

But it ended printing only one line with the context info on the first line Sim101 and not on the other lines.

2012-11-26 15:09:47.9777 NinjaTrader.Strategy.LODHOD.OnStartUp Debug   Sim101
2012-11-26 15:09:48.3996 NinjaTrader.Strategy.LODHOD.OnBarUpdate Trace   BAR UPDATE
2012-11-26 15:09:49.7902 NinjaTrader.Strategy.LODHOD.EntryOrders Info   PLACED ENTRY ORDERS

How do I print the Sim101 on all the log lines?

Answer 1

The {event-context} LayoutRenderer writes a value from the LogEventInfo object's Properties property.

Properties is a dictionary where you can store named values that you want NLog to add to each log message.

If you want to tag each log message with the "StrategyId" that is in effect when the message is logged, you should create your LogEventInfo objects something like this:

LogEventInfo theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name);
theEvent.Properties["StrategyId"] = "Sim101";
Logger.Log(theEvent);

Your layout would look like this:

fileTarget.Layout =  "${longdate} ${callsite} ${level} ${event-context:item=StrategyId}  ${message}";

If you want your logging call sites to be less verbose, you could use GlobalDiagnosticContext or MappedDiagnosticContext.

private void ApplyStrategyABC()
{
  NLog.GlobalDiagnosticContext.Set("StrategyId","ABC");
  //Do some stuff
  LogEventInfo theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name);
  Logger.Log(theEvent);

  NLog.GlobalDiagnosticContext.Remove("StrategyId");
}

private void ApplyStrategyDEF()
{
  NLog.GlobalDiagnosticContext.Set("StrategyId","DEF");
  //Do some stuff
  LogEventInfo theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name);
  Logger.Log(theEvent);

  NLog.GlobalDiagnosticContext.Remove("StrategyId");
}

Using a layout like this:

fileTarget.Layout =  "${longdate} ${callsite} ${level} ${gdc:item=StrategyId}  ${message}";

Will cause each log message to be tagged with the current value of "StrategyId" in the global dictionary.

For fun you could also make sort of a fluent API extension method that would apply your properties to the LogEventInfo objects that you create. Something like this (untested):

LogEventInfo WithProperty(this LogEventInfo theEvent, string name, string value)
{
  theEvent.Properties[name] = value;
  return theEvent;
}

You could then use it like this:

var theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name).WithProperty("StrategyId", "ABC");

And this:

var theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name).WithProperty("StrategyId", "ABC").WithProperty("SomethingElse", someLocalVariable);

If you want to be more explicit (and reduce possible typo errors), you might make more specific extension methods like this:

LogEventInfo WithStrategy(this LogEventInfo theEvent, string strategy)
{
  theEvent.Properties["StrategyId"] = strategy;
  return theEvent;
}

LogEventInfo WithCurrency(this LogEventInfo theEvent, string currency)
{
  theEvent.Properties["Currency"] = currency;
  return theEvent;
}

var theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", this.Account.Name).WithStrategy("ABC").WithCurrency("US dollars");

EDIT: Most people use the Logger.Info, Logger.Debug, Logger.Trace, etc methods to write their log messages rather than creating a LogEventInfo and calling Log for each message. There is perhaps more flexibility available if you create your LogEventInfo objects explicitly, but it also makes your work more complicated.

If you want to use the Logger.Info, Logger.Debug, etc methods and decorate each log message with additional properties, you can still do that.

Let's say you have two methods (like I described above) to apply two different strategies: ABC and DEF:

Use a layout like this:

fileTarget.Layout =  "${longdate} ${callsite} ${level} ${gdc:item=StrategyId}  ${message}";

public class MyClass
{
  private static readonly Logger logger = LogManager.GetCurrentClassLogger();

  private void ApplyStrategyABC()
  {
    NLog.GlobalDiagnosticContext.Set("StrategyId","ABC");
    //Do some stuff

    logger.Debug("Hello from ABC!"); 

    var x = CalculateSomeValue();

    logger.Debug("Value = {0}", x);

    NLog.GlobalDiagnosticContext.Remove("StrategyId");      
  }

  private void ApplyStrategyDEF()
  {
    NLog.GlobalDiagnosticContext.Set("StrategyId","DEF");
    //Do some stuff

    logger.Debug("Hello from DEF");

    var x = CalculateSomeValue();

    logger.Debug("Value = {0}", x);

    NLog.GlobalDiagnosticContext.Remove("StrategyId");      
  }
}

In you program call your two strategies:

var myClass = new MyClass();

myClass.ApplyStrategyABC();
myClass.ApplyStrategyDEF();

In each case, the messages logged will be tagged with the "StrategyId" that is set inside of the corresponding function.

If you DO want to create and use LogEventInfo objects to create your messages, then you have to realize that the Properties of one LogEventInfo object instance apply ONLY to that instance. If you create a LogEventInfo, set its Properties, log it, then log a message using Logger.Info, Logger.Debug, etc then you WILL NOT see the properties that you set on the original LogEventInfo.

For example,

var logger = LogManager.GetCurrentClassLogger();
var theEvent = new LogEventInfo(NLog.LogLevel.Debug, "", "Hello 1");
theEvent.Properties["StrategyId"] = "ABC";
//This message will be tagged with StrategyId = ABC if the layout uses the event-context LayoutRenderer
logger.Log(theEvent);

//This message will NOT be tagged with StrategyId = ABC because that value was only added to the LogEventInfo
//object that was created above.  Another way to think about this is that internally
//NLog creates a LogEventInfo for each message that is logged via the Debug, Trace, etc
//methods.
logger.Debug("Hello 2");

I would recommend using the Logger.Info, Logger.Debug, Logger.Trace, etc methods to log your messages and using either GlobalDiagnosticsContext or MappedDiagnosticsContext to specify the additional information that you want to be included in each log message.

Generally, I think that I would also recommend that you use EITHER the Logger.Info, Logger.Debug, Logger.Trace methods OR LogEventInfo + Logger.Log, but not BOTH. Using both, especially if you are trying to add additional context values (StrategyId) can become confusing.

I can make an analogy to installing software. Typically when you install software on your computer, you have the choice of taking the "Typical" install where you let the installer install the components that it wants to install or "Custom" where you pick and choose the components that you want to install. I don't know about you, but I usually choose the "Typical" install. Using Logger.Info, Logger.Debug, Logger.Trace is like the "Typical" install. These are the most commonly used methods for logging. Using LogEventInfo + Logger.Log is more like choosing "Custom" install. The implication if you are using LogEventInfo is that the "typical" logging methods don't meet your needs.

As you work with NLog you will become more familiar with how it works and some of these issues will become more obvious to you.

Note that GlobalDiagnosticsContext is truly global. It is a static object. So, if you are multithreading, you have the potential for conflict if two threads are trying to add a value with the same name to the dictionary.

MappedDiagnosticsContext is thread local (it uses a thread static dictionary to store its values), so it is probably better to use in a multithreading situation.

If you want to get fancy and automatically scope the values that you put in the GlobalDiagnosticsContext (or the MappedDiagnosticsContext), you could create a class like this:

public class ScopedGlobalContext : IDisposable
{
  private string n;
  private string v;

  public ScopedGlobalContext(string name, string value)
  {
    n = name;
    v = value;
    NLog.GlobalDiagnosticsContext.Set(n, v);
  }

  public void Dispose()
  {
    NLog.GlobalDiagnosticsContext.Remove(n);
  }
}

And you could use it like this:

  private void ApplyStrategyDEF()
  {
    using (new ScopedGlobalContext("StrategyId", "DEF"))
    {
      //Do some stuff

      logger.Debug("Hello from DEF");

      var x = CalculateSomeValue();

      logger.Debug("Value = {0}", x);
    }
  }

This will put the StrategyId, DEF name value pair in the GlobalDiagnosticsContext dictionary when the using scope begins and will remove it when the using scope exits.