none
EventLog.EntryWritten firing for events in the past RRS feed

  • Question

  • Hello - I have a windows service that will setup a delegate for the EntryWritten event. My understanding of this event handler is that it will only fire when an entry is written to the event log. However, events from the past that are contained in that eventlog (I'm talking events that occurred in some cases 2 years ago) that were previously written also cause the delegate to fire. For example today, 4/8/2015, I see events that occurred back in 2013 acting as though they were written today.

    Is this behavior expected? It seems as thought it is a bug or possibly something I am not doing correctly in the code. Any light that can be shed on this situation would be great.


            private static bool SetupListeners()
            {
                var logsConfigurationSection = ConfigurationManager.GetSection("LogsSection") as LogsConfigurationSection;
    
                if (logsConfigurationSection == null) return false;
    
                for (var incr = 0; incr < logsConfigurationSection.Logs.Count; incr++)
                {
                    List<EventLog> el;
    
                    if (logsConfigurationSection.Logs[incr].Wildcard)
                        el = EventLog.GetEventLogs()
                            .Where(w => w.Log.ToLower().StartsWith(logsConfigurationSection.Logs[incr].Name.ToLower())).ToList();
                    else
                        el = EventLog.GetEventLogs()
                            .Where(w => w.Log.ToLower().Equals(logsConfigurationSection.Logs[incr].Name.ToLower())).ToList();
    
                    foreach (var eLog in el)
                    {
                        Log.Information("Setting up EntryWritten listener for {0}. Configuration is name {1} and wildcard {2}",
                        eLog.Log, logsConfigurationSection.Logs[incr].Name, logsConfigurationSection.Logs[incr].Wildcard);
    
                        eLog.EntryWritten += OnEntryWritten;
                        eLog.EnableRaisingEvents = true;
    
                        ListeningLogs.Add(eLog);
                    }
                }
    
                return true;
            }

    EDIT 1: This is C# 5.0, .NET Framework 4.5 and the service runs on Windows Server 2008 and/or Windows Server 2012 (core and full).

    EDIT 2: Looks like this situation has been present for some time given this post on SO:

    http://stackoverflow.com/questions/19137560/eventlog-entrywritten-event-handles-events-from-the-past

    As a stopgap in the code, I plan to interrogate EventLogEntry.TimeWritten (converted to UTC) relative to DateTime.UtcNow with a "buffer" of 2 minutes. This is inside of OnEntryWritten (the delegate called):

    if (elEntry.TimeWritten.ToUniversalTime() < DateTime.UtcNow.AddMinutes(-_bufferMins))
                    return;

    Regards,
    Ryan





    • Edited by Ryan Koziel Wednesday, April 8, 2015 8:56 PM More info and workaround
    Wednesday, April 8, 2015 6:31 PM

All replies

  • Hello Ryan,

    >>Is this behavior expected?

    This could be, please check the remarks for this event:

    The system responds to WriteEntry only if the last write event occurred at least six seconds previously. This implies you will only receive one EntryWritten event notification within a six-second interval, even if more than one event log change occurs. If you insert a sufficiently long sleep interval (around 10 seconds) between calls to WriteEntry, you are less likely to miss an event. However, if write events occur more frequently, you might not recieve the event notification until the next interval. Typically, missed event notifications are not lost, but delayed.

    So if there is a sufficiently long sleep interval, missed event notifications are not lost, but delayed. Please check if you are in this scenario.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    • Marked as answer by Fred BaoModerator Wednesday, April 22, 2015 11:00 AM
    • Unmarked as answer by Ryan Koziel Wednesday, April 22, 2015 2:22 PM
    Thursday, April 9, 2015 3:38 AM
    Moderator
  • Hi Fred - Thanks for the response. I did run across that in the documentation on that event, however I did not see how that applies. In short the service starts one thread that calls the method I noted above and "subscribes" to that event (I'll admit there is polling involved but only for pushing said messages downstream to our data store on X interval - basically flushing a list). Everything works as I would expect it to as messages are written, and the interval when EntryWritten fires is arbitrary for our needs as long as it is reasonable (not minutes...although when an entry is written 6 seconds seems like a rather long time), but it is bizarre in that the event fires for a message (in most cases messages, in succession) written in the past...distant past, in some cases predating the existence of this service. The messages are in our data store.

                try
                {
                    if (!SetupListeners())
                        throw new ApplicationException("Failed to setup log listeners.");
    
                    _timer.Enabled = true;
                }


    {
        "CollectionDateTime": "2015-04-08T08:57:53.1724940Z",
        "Hostname": "SomeHost",
        "Domain": "SomeDomain.com",
        "Category": "(0)",
        "CategoryNumber": 0,
        "EntryType": "Information",
        "Index": 90420,
        "EventId": 1073748860,
        "Message": "The WMI Performance Adapter service entered the running state.",
        "Source": "Service Control Manager",
        "Channel": "System",
        "TimeGenerated": "01/23/2014 12:07:37",
        "TimeWritten": "01/23/2014 12:07:37"
    }


    Regards,

    Ryan


    Ryan Koziel




    • Edited by Ryan Koziel Thursday, April 9, 2015 5:20 AM
    Thursday, April 9, 2015 4:51 AM
  • Hello Ryan,

    I created a small demo which could make the scenario: the event mesage could be delayed:

    using System;
    using System.Collections.Generic;
    using System.Diagnostics;
    using System.Linq;
    using System.Text;
    using System.Threading;
    using System.Threading.Tasks;
    
    namespace P20150409
    {
        class Program
        {
    
            static void Main(string[] args)
            {
                EventLog myNewLog = new EventLog("Application", ".", "dotNET Sample App");
    
                myNewLog.EntryWritten += new EntryWrittenEventHandler(MyOnEntryWritten);
                myNewLog.EnableRaisingEvents = true;
                while (true)
                {
                    System.Threading.Thread.Sleep(3000);
                    string EventWriteTime = DateTime.Now.ToString();
                    Console.WriteLine("Log is written at" + EventWriteTime);
                    myNewLog.WriteEntry("Test message written at" + EventWriteTime + " " + System.Threading.Thread.CurrentThread.ManagedThreadId, EventLogEntryType.Information);
                    Console.WriteLine();
                }
                Console.ReadLine();
    
            }
    
            
            private static void MyOnEntryWritten(object sender, EntryWrittenEventArgs e)
            {
                System.Threading.Thread.Sleep(6000);
                Console.WriteLine("EntryWritten event is fired at" + DateTime.Now.ToString());
                Console.WriteLine("Log time is" + e.Entry.Message);
                Console.WriteLine();
            }
        }
    }
    

    This is the result:

    As we can see that the interval between event fired time and the current written time is bigger and bigger, so it could be that an event is fired 2 year later...And for reason, we can see that it is becuase i set the event sleep 6s whenever it is fired. So i am wondering in your event, there is a similar feature which causes this delay.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Friday, April 10, 2015 1:23 AM
    Moderator
  • Hi Fred - I've been working through some other issues and haven't had the time to get back to this.  I unmarked the proposed answer as it doesn't answer the problem really.

    All that we have is a service that is "listening" on certain event logs. Think of it like a log forwarder and as such it is not writing events. It is indeed receiving messages from the past as if they were written more recently as evidenced by the JSON snippet above (compare CollectionDateTime to TimeWritten and/or TimeGenerated). In other words the service received that message on 4/8/2015 via the EntryWritten event...but the event actually occurred, and was written, back on 1/23/2014.

    As I dig into this I'll add my findings here.

    Regards,

    Ryan


    Ryan Koziel

    Wednesday, April 22, 2015 2:28 PM
  • Hello Ryan,

    >>In other words the service received that message on 4/8/2015 via the EntryWritten event...but the event actually occurred, and was written, back on 1/23/2014.

    In my opinion, this should be the scenario that an event is delayed occurred and the document of this event also has a description for it, in your case, this delay seems to be very long.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Saturday, April 25, 2015 2:33 AM
    Moderator
  • I'm facing exactly the same issue. What I did to solve it was to store the last read datetime so I can compare it with the new logs that I get from the OnEntryWritten. It's still a performance issue, but it's better than nothing.

    public void OnEntryWritten(Object source, EntryWrittenEventArgs e)
            {
                var entry = e.Entry;
                var timeWritten = entry.TimeWritten;
    
                // When overwrite policy is enabled, this will trigger for all elelemnts when it starts writing new ones
                if (timeWritten >= _lastDateSaved)
                {
                    _lastDateSaved = timeWritten;
                    Console.WriteLine($"({_counter++}) {entry.TimeWritten}");
                }
                else
                {
                    //Console.WriteLine($"Ignoring element with ts: {timeWritten}");
                }
            }


    Friday, November 23, 2018 3:25 PM