Can't update EventLog's Source property

[ArchonMegalon]

KAV.Tools.Logging.1.0.0.21.zip

Hi!

My first report, so please be gentle... ;)

The important thing is happening in the LogInternal function of my custom (from NLog.Logger inherited) Loggerclass:

logEvent.Properties["MySource"] = useSource; <-- this is set per call

The second time the function is called (and useSource is different), of course the Properties are set, but the EventLogTargets SourceAttribute is not updated! It has always the value from the first call.

EventID is updated.

Type: Bug
NLog version: 4.3.5

Platform: .Net 4.5 (don't know what else - haven't tried it)

Current NLog config:

<?xml version="1.0" encoding="utf-8"?>
<nlog throwExceptions="true" xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <!--   See http://nlog-project.org/wiki/Configuration_file for information on customizing logging rules and outputs. -->
  <!--${shortdate}-->
  <targets>
     <target xsi:type="EventLog" name="ELNoFileName" machineName="."
            source="${event-properties:item=MySource}" log="Application"
            eventId="${event-properties:EventID}"
            layout="ELNoFileName (${event-properties:item=MySource}): ${message}${newline}${newline}Pid: ${processid}${newline}Call site: ${callsite:className=true:methodName=true}${newline}Logger: ${logger}${newline}${exception:format=tostring}"/>
  </targets>
  <rules>
    <logger name="*" minlevel="Trace" writeTo="ELNoFileName">
      <filters>
        <when condition="length('${event-properties:item=FileName}') > 0" action="Ignore" />
      </filters>
    </logger>
  </rules>
</nlog>

public partial class LoggerBase : NLog.Logger
{
 private void LogInternal(LogLevel level, object message = null, Exception exception = null, int? eventId = null)
        {
            var logEvent = new LogEventInfo
            {
                Message = message?.ToString() ?? String.Empty,
                Exception = exception,
                Level = level,
                LoggerName = this.Name

            };


            var stack = new StackTrace(true);
            int userFrameIndex = -1;
            MethodBase userMethod = null;

            for (int i = 0; i < stack.FrameCount; ++i)
            {
                var frame = stack.GetFrame(i);
                var method = frame.GetMethod();
                if (method?.DeclaringType != null)
                {
                    if (method.DeclaringType == this.GetType() || this.GetType().IsSubclassOf(method.DeclaringType))
                    {
                        // skip all methods of this type
                        continue;
                    }
                    if (method.DeclaringType.Name == this.GetType().Name)
                    {
                        // skip all methods of this type
                        continue;
                    }
                    if (method.DeclaringType.Name == typeof(LoggerBase).Name)
                    {
                        continue;
                    }
                }

                if (method?.DeclaringType?.Assembly == SystemAssembly)
                {
                    // skip all methods from System.dll
                    continue;
                }

                userFrameIndex = i;
                userMethod = method;
                break;
            }
            string currentFile = "unknown";
            int currentLine = 0;
            if (userFrameIndex >= 0)
            {
                currentFile = stack.GetFrame(userFrameIndex).GetFileName();
                currentLine = stack.GetFrame(userFrameIndex).GetFileLineNumber();
                logEvent.SetStackTrace(stack, userFrameIndex);
                if (userMethod?.DeclaringType != null)
                {
                    logEvent.LoggerName = userMethod.DeclaringType.FullName;
                }
            }

            if (logEvent.Level > LogLevel.Info)
            {
                logEvent.Properties["FileName"] = currentFile;
                logEvent.Properties["LineNumber"] = currentLine;
            }
            if (eventId.HasValue)
            {
                logEvent.Properties["EventID"] =  eventId.Value;
            }
            else
            {

                GlobalLoggerBaseEventId id = new GlobalLoggerBaseEventId()
                {
                    Filename = currentFile,
                    LineNumber = currentLine,
                    LogLevel = logEvent.Level
                };
                if (id.DicKey == new GlobalLoggerBaseEventId().DicKey)
                {
                    logEvent.Properties["EventID"] = 0;
                }
                else
                {


                    GlobalLoggerBaseEventId dicId;
                    if (GlobalLoggerBase.GlobalEventIds.TryGetValue(id.DicKey, out dicId))
                    {
                        logEvent.Properties["EventID"] = dicId.EventId;
                    }
                    else
                    {
                        lock (GlobalLoggerBase.GlobalEventIdCountLock)
                        {
                            GlobalLoggerBase.GlobalEventIdCount++;
                            id.EventId = GlobalLoggerBase.GlobalEventIdCount;
                            if (!GlobalLoggerBase.GlobalEventIds.TryAdd(id.DicKey, id))
                                throw new NLogRuntimeException(
                                    "Could not add Event to GlobalLoggerBase.GlobalEventIds: " + id.ToString());
                            logEvent.Properties["EventID"] = id.EventId;
                        }
                    }
                }
            }
            string useSource = GetEventlogSource(userMethod, logEvent);


            logEvent.Properties["MySource"] = useSource;


            (this as Logger).Log(logEvent);
        }

        private static string GetEventlogSource(MethodBase userMethod, LogEventInfo logEvent)
        {
            string useSource = null;
            ObjectCache cache = MemoryCache.Default;
            var eventLogSource = !string.IsNullOrEmpty(userMethod?.DeclaringType?.Assembly.GetName().Name)
                ? userMethod.DeclaringType.Assembly.GetName().Name
                : "Application Error";
            if (cache.Contains(eventLogSource))
                {
                    useSource = cache.Get(eventLogSource) as String;
                }
            if (String.IsNullOrEmpty(useSource))
            {
                try
                {
                    if (!System.Diagnostics.EventLog.SourceExists(eventLogSource))
                    {
                        try
                        {
                            System.Diagnostics.EventLog.CreateEventSource(eventLogSource, "Application");
                        }
                        catch (Exception e)
                        {
                            System.Diagnostics.Trace.TraceInformation(e.ToString());
                        }
                    }
                }
                catch (Exception)
                {
                    try
                    {
                        System.Diagnostics.EventLog.CreateEventSource(eventLogSource, "Application");
                    }
                    catch (Exception e)
                    {
                        System.Diagnostics.Trace.TraceInformation(e.ToString());
                    }
                }
                bool itExists = false;
                try
                {
                    itExists = System.Diagnostics.EventLog.SourceExists(eventLogSource);
                }
                catch (Exception)
                {
                    //do nothing, thats just to get the bool-value
                }
                if (!itExists)
                {
                    string substring = "Application Error";
                    logEvent.Message = "Eventlog Source " + eventLogSource + " does not exist!" +
                                       Environment.NewLine + Environment.NewLine + "And now the real log-entry: " +
                                       Environment.NewLine + logEvent.Message;
                    useSource = substring;
                }
                else
                {
                    useSource = eventLogSource;
                }

                // Store data in the cache
                CacheItemPolicy cacheItemPolicy = new CacheItemPolicy
                {
                    AbsoluteExpiration = DateTime.Now.Add(TimeSpan.FromDays(1))
                };
                cache.Add(eventLogSource, useSource, cacheItemPolicy);
            }
            return useSource;
        }
}

And here only the "helping Classes"...

  public class GlobalLoggerBaseEventId
    {
        internal string DicKey => Filename + ":" +  LineNumber;

        public NLog.LogLevel LogLevel { get; set; }

        public int EventId { get; set; }
        public string Filename { get; set; }
        public int LineNumber { get; set; }
        public string FunctionName { get; set; }
        public string FirstMessage { get; set; }

        public override string ToString()
        {
            var strOut =
                $"{LogLevel} - EventId:{EventId} from {Filename}:{LineNumber}";
            return strOut;
        }
    }
    public static partial class GlobalLoggerBase
    {
        private static ConcurrentDictionary<string, GlobalLoggerBaseEventId> _globalEventIds = new ConcurrentDictionary<string, GlobalLoggerBaseEventId>();
        public static ConcurrentDictionary<string, GlobalLoggerBaseEventId> GlobalEventIds => _globalEventIds;

        public static int GlobalEventIdCount = 10000;
        public static Object GlobalEventIdCountLock = new Object ();
    }

In case of a BUG:

• What is the current result?

Currently the Source source="${event-properties:item=MySource}" is set only once - the first time.

• What is the expected result?

I would have thought it would be set (or updated) in every logEvent.

• Did you checked the Internal log?

Yes (a bit). Didn't find useful information in there (regarding my "problem").

• Please post full exception details (message, stacktrace, inner exceptions)

No exception - it just uses the first Source. All Sources are registerd by the way...

• Are there any work arrounds? yes/no

Well - one can always "hardcode" the source in the EventLog or use special rules/filters for special targets. But that's not really confinement.

• Is there a version in which it did worked?

Don't think so - I just started using NLog in that way.

• Can you help us by writing an unit test?

I guess... Since this is my first bug-report on github I'm sure willing to try...

I made a nuget-package out of this - would that be helpful?

[304NotModified]

We render every event the filename. The cachedCleanedFileNamed is not used when the FileName has layout renderers.

see:

        /// <summary>
        /// Writes the specified logging event to a file specified in the FileName 
        /// parameter.
        /// </summary>
        /// <param name="logEvent">The logging event.</param>
        protected override void Write(LogEventInfo logEvent)
        {
            var fileName = Path.GetFullPath(GetCleanedFileName(logEvent));
            byte[] bytes = this.GetBytesToWrite(logEvent);
            ProcessLogEvent(logEvent, fileName, bytes);
        }

        private string GetCleanedFileName(LogEventInfo logEvent)
        {
            if (this.FileName == null)
            {
                return null;
            }
            return cachedCleanedFileNamed ?? CleanupInvalidFileNameChars(this.FileName.Render(logEvent));
        }

But are your really using the LoggerBase? I would recommend to write for LoggerBase to the InternalLogger

[ArchonMegalon]

The source is the problem, not the filename.

Also I inherited from NLog.Logger. I just called MY class LoggerBase (exactly KAV.Tools.Logging.LoggerBase), since I'm going to inherit from it another time (it will be KAV.Tools.Logging.Logger : KAV.Tools.Logging.LoggerBase : NLog.Logger).

"My" LoggerBase handles all the stuff I want to handle it and "my" Logger is only for special customizing in the specific project.

[304NotModified]

Ow did misread it. Will check again

[304NotModified]

indeed, the eventLogInstance is cacked (wrongly)

relevant code:

        /// <summary>
        /// Get the eventlog to write to.
        /// </summary>
        /// <param name="logEvent">Event if the source needs to be rendered.</param>
        /// <returns></returns>
        private EventLog GetEventLog(LogEventInfo logEvent)
        {
            return eventLogInstance ?? (eventLogInstance = new EventLog(this.Log, this.MachineName, this.Source.Render(logEvent)));
        }

This is indeed a bug!

[ArchonMegalon]

Wow! I'm glad my first report actually was no "error" (on my side) ;)
Great work by the way - NLog is awesome!

[304NotModified]

I'm a bit busy these days. Do you think you can fixed this bug and send a PR?

[ArchonMegalon]

ah... hm... never did such a thing and since I'm new to NLog.
But hey - I can at least try it before failing... :)
I will get to it probably on Monday!

[304NotModified]

you have to change EventLogTarget.cs

It's a relative easy target.

GetEventLog should also check (and remember) this.Log, this.MachineName, and Source.Render(logEvent), for using the cache

[ArchonMegalon]

Hi!

Sorry, I have no idea how to upload my patched EventLogTarget.cs

It's a real simple thing:

 private EventLog GetEventLog(LogEventInfo logEvent)
 {
            if (eventLogInstance?.Source == this.Source.Render(logEvent))
                return eventLogInstance ?? (eventLogInstance = new EventLog(this.Log, this.MachineName, this.Source.Render(logEvent)));
            return eventLogInstance = new EventLog(this.Log, this.MachineName, this.Source.Render(logEvent));
 }

Please copy/paste it and thank you for your amazing work!

[s-sreenath]

@ArchonMegalon Thanks. I will take a look at this.

[s-sreenath]

UPDATE: I am trying to get some Unit Tests around the fix. Once those are completed will send in a PR.

[304NotModified]

Cool!

[s-sreenath]

PR: #1548

[304NotModified]

Fixed and online (NLog 4.3.6)

Thanks @page-not-found !