Issue (maybe) with LogEventInfo cache (and solution)

[Claudio A.]

Hello,

preamble: i don't know if the 'issue' i'm talking about in this post is a real issue, or rather a 'by design' behavior, even caused to my wrong usage of the library. I'd be pleased if Jaroslaw (or some other Nlog guru) could intervene to comment/explain/discuss (btw, thank you for this excellent product).


First of all, i prefer to use the NLog library via LogEventInfo objects. That is:


// *** start of code example ************

NLog.Logger theLogger = NLog.LogManager.GetLogger("JaroslawIsGreat");

NLog.LogEventInfo lei = new NLog.LogEventInfo();
lei.Level = NLog.LogLevel.Warn;

lei.Message = "NLog is great";
theLogger.Log(lei);

// *** end of code example ************


instead of the perhaps more common way:


// *** start of code example ************

NLog.Logger theLogger = NLog.LogManager.GetLogger("JaroslawIsGreat");
theLogger.Log(NLog.LogLevel.Warn, "NLog is great");

// *** end of code example ************


Anyway, this should be an allowed way to use the library, shouldn't?

The problem is that if i change the Message property of the LogEventInfo object, and try to log it again,   i get the same output as the first log. For example:


// *** start of code example ************

NLog.Logger theLogger = NLog.LogManager.GetLogger("JaroslawIsGreat");

NLog.LogEventInfo lei = new NLog.LogEventInfo();
lei.Level = NLog.LogLevel.Warn;

lei.Message = "NLog is great";
theLogger.Log(lei);

// Change the Message property, and log again
lei.Message = "NLog is amazing";
theLogger.Log(lei);


// *** end of code example ************

i get this output (in the configured log target):

NLog is great
NLog is great

instead of the expected:

NLog is great
NLog is amazing


This happens because the Nlog engine caches internally the log output, in order (i suppose) to optimize speed in case your configuration contains two or more targets with the same layout.

But, in my opinion, the cache 'scope' should remain internal to NLog code, and shouldn't affect user code.  
In other words, in the code example above, the cache shouldn't 'survive' between the first and second 'theLogger.Log(lei)' user calls.

Of course this is my personal opinion, and it could not consider (or even conflict with) some design/project implications that i'm unaware of: again, i'd be pleased to hear your opinions.

Anyway, i made some modifications to NLog code to overcome this 'issue'. Comments are welcome, and feel free to use or modify them (of course, at your own risk).

In:

Nlog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory)

i surrounded the whole method code with this try/finally block:

try
{
        ...original NLog code...
}
finally
{
        if (logEvent != null)
        {
                logEvent.ClearCachedLayout();
        }
}


then i added the metod ClearCachedLayout() to NLog.LogEventInfo class:

internal void ClearCachedLayout()
{
        if (_layoutCache != null)
                _layoutCache.Clear();
}


This empties the LogEventInfo cache after each Log operation, so the above code example will write the 'expected' output:


NLog is great
NLog is amazing


Regards,

        Claudio