1

I created a Log File class that uses NLog with the hopes of writing to multiple log files at the same time. This seems to work fine until I add variables to the mix.

Problem

Changing the variable seems to change that variable setting for all instances of the log file instead of the particular instance I am working with.

My Code

Here is how I have the programming structured:

LogClass - Basically a wrapper to give me some additional functionality. The 'SetVariable' is what I am using to set the particular variable (called dqwAlertName)

Logging Class

With this log class, I am passing in the specific logger that I want to use like this:

Public iLogger as new Logger(NLog.LogManager.GetLogger("dataQualityWatcher"),True)

That statement instantiates the logging class with the "dataQualityWatcher" logger and sets Debug=True (which I simply use to allow a more verbose logging that can be turned on and off).

With that said... The statement above is ALSO within another class object:

dataQualityWatcher Class - This is a 'watcher' that is called many times over and runs continuously. If you familiar with FileSystemWatcher, it works similarly to that. It basically watches data for a specific value and raises an event.

dataQualityWatcher Class

Inside THIS class is where I instantiate the logger as mentioned above with the following code:

Public iLogger as new Logger(NLog.LogManager.GetLogger("dataQualityWatcher"), True)

iLogger.SetVariable("dqwAlertName", _AlertName)

The first line instantiates, the second line will set the variable. The Logging Class SetVariable method is pretty basic:

Public Sub SetVariable(variableName as string, value as String)
    'Set variable context for the logger
    NLog.LogManager.Configuration.Variables(variableName) = value
End Sub

I am using that variable within the NLog.config file in the following manner:

<variable name="LogLayout" value="[${date:format=MM/dd/yyyy h\:mm\:ss.fff tt}] [${gdc:item=location}]  |  ${level}  | ${message}" />
<variable name="InfoLayout" value="[${date:format=MM/dd/yyyy h\:mm\:ss.fff tt}] ${gdc:item=SoftwareName} Version ${gdc:item=SoftwareVersion}  -  ${message}" />
<variable name="DebugInfoLayout" value="[${date:format=MM/dd/yyyy h\:mm\:ss.fff tt}] ${message}" />
<variable name="logDir" value="C:/Log/PWTester/" />
<variable name="dqwAlertName" value="" />

<targets>
    <target name="dataQualityWatcher" xsi:type="File" fileName="${logDir}/LogFiles/${var:dqwAlertName}-DataQualityWatcher.log" layout="${LogLayout}" />
</targets>

<rules>
    <logger name="dataQualityWatcher" minlevel="Trace" writeTo="dataQualityWatcher" />
</rules>

THE PROBLEM:

I run multiple 'watchers' (as I call them) with the following code to create that object and assign properties:

 dataWatch.Add(New dataQualityWatcher(True) With {.Tags = lstTags, .AlertTimerInterval = Convert.ToInt64(intTimerMilliseconds), .AlertGroupID = Convert.ToInt64(CARow(0)), .EmailGroupID = Convert.ToInt64(CARow(1)), .CustomSubject = CARow(3), .CustomMessage = CARow(4), .AlertName = DataAlertGroupName, .Debug = blnVerboseLogging, .HistorianServer = SH})

Multiple Version Example

I run the code above where: .AlertName = {"Test1", "Test2", "Test3"}. Other parameters would also change and a new object is instantiated each time. In this example there are 3 dataQualityWatcher objects instantiated, which also instantiates 3 Logger objects.

Each time a new dataQualityWatcher object is instanciated, it instanciates a Logger, which would then write to the file. The AlertName variable is passed on through the SetVariable method above.

I would expect 3 log files to be written:

  1. Test1-DataQualityWatcher.log
  2. Test2-DataQualityWatcher.log
  3. Test3-DataQualityWatcher.log

This DOES happen. However, the last dataQualityWatch object that is created will run the SetVariable method = "Test3" (in this example). Now that variable is set and all 3 Loggers will begin logging to that file (i.e., Test3-DataQualityWatcher.log).

I can only assume that there is a better way to do this with variables such that they are for the life of that particular log instance, but I can't seem to figure it out!

Thanks in advance and sorry for the VERY, VERY long post.

Julian
  • 33,915
  • 22
  • 119
  • 174
Andrew
  • 437
  • 7
  • 18

1 Answers1

1

As far as I understand your are trying to log to multiple files, with one target.

This won't work well with the use of variables as they are static (Shared in VB.net) - so this isn't threadsafe.

Other options to do this are:

  1. Create multiple file targets in your nlog.config and setup the right <rules>, or
  2. Pass extra properties for every message, and use event-properties: fileName="${logDir}/LogFiles/${event-properties:dqwAlertName}-DataQualityWatcher.log", VB.NET call:

    Dim theEvent As New LogEventInfo(LogLevel.Debug, "", "Pass my custom value")
    theEvent.Properties("MyValue") = "My custom string".
    

    You could write a sub class for Logger to make it less verbose. Or

  3. Create the targets & rules programmatically (in VB.NET). See tutorial (in C#)

If performance is very important, choose for 1 or 3.

Julian
  • 33,915
  • 22
  • 119
  • 174
  • #1 isn't an option because there can be any number of 'watchers', which equates to log files. #2 works pretty well, but there are still times when items that should go into 1 log file end up in another. I'm guessing that the way NLog is created, that even the event properties are shared? I see some cross-logging between the 3 files. The other logs that are separate targets entirely are also jumping into those files on occasion. It is a bit maddening. – Andrew Dec 01 '16 at 20:49
  • It appears that this only happens within the first few minutes of the application's life. Then it settles down. Doesn't make much sense to me yet. – Andrew Dec 01 '16 at 21:22
  • The event properties are always thread safe. Changing the variables isn't. – Julian Dec 01 '16 at 21:25