sps_perry

Overview: I get runtime errors using the .NET EventLog class in very simple traversal, due to event entries being written and overwritten while I'm reading the log. How should I as a developer use this class to query a live event log How do you avoid or handle the exceptions which the simple foreach EventLogEntry iterator throws as things change

I want to read all the events in a particular log, which are newer than a certain date.

Originally I tried this

for (int i=eventLog.Entries.Count-1; i>=0; --i)

{

EventLogEntry entry = eventLog.EntriesIdea;

if (entry.TimeWritten < cutoffTime) return;

/* record stuff */

}

When I got sporadic errors with that, because of event log entries being written and overwritten during the time my code was running and trying to read them, I switched to using an iterator:

foreach (EventLogEntry entry in eventLog.Entries)

{

if (entry.TimeWritten >= cutoffTime)

{

/* record stuff */

}

}

Unfortunately I still get sporadic errors, usually exceptions due to invalid argument, and the debugger pinpoints them as occurring in the "foreach" line itself.

I've looked at the windows API, and seen a sample where you first ask for the record location of the oldest record, and then ask for records one after another in forward sequence (using a keyword for forward sequence, not specifying a record number).

I've not tried that - I'm not sure it will avoid the bug/error/problem.

I assume that what is happening, is that the iterator is trying to start at the oldest entry, but that after the iterator grabs the record number of the oldest entry, the next events written to the log will naturally be written right there (because the log is set to overwrite as necessary, and it is on a production server, so it is naturally full and constantly overwriting old events).

I'm afraid this may mean that the builtin iterator will be buggy -- if it tries to grab the records starting at what was recently the oldest record number, won't it actually get the brand new records that were written during the milliseconds since it grabbed the record number

I mean, if the foreach iterator implementation asks for the starting point, and windows says start at record 222222, and then the foreach iterator gets the first event -- lets say it gets it in time to beat the next live record -- and then it hands it to my code, and my code looks at it and finds it to be old, then I loop and control passes back to the iterator, and the iterator gets record 222223, which is now one of the newest records, because (let's say) 15 new event records were written in the meantime, then the next event entry it hands me is a brand new one.

What concerns me is that I'm not getting entries in a contiguous time batch, so if the iterator throws an exception (which it does from time to time, I assume because the total number of records is not constant but varies depending how big the current ones are -- bigger ones will cause the total number to be fewer, so the upper limit on valid record numbers may change dynamically), then I don't have a good way to go back and try again.

I mean, if I received some old and some new records, then the iterator broke, and then I go back to get more, I will naturally ask for all the ones which are newer than the latest one I received -- but that means I will miss many. (In actual usage I know I'm missing more than 60,000 on one server, when I ask for all the ones later than the latest one I've recorded so far).



Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

TaylorMichaelL

The enumerator actually queries the data on the fly as you request it so I'm not sure what exception you might be getting. In theory you shouldn't have a problem of the events being overwritten but even if you did you'd just be missing the data that you've already read. However if you really want to get a snapshot of the data in time then you can use CopyTo to get an array of the current entries. However this is going to eat up a lot of memory. You'll then have to ask for a copy again and filter out the events you've already read. It'll be unpleasant. Can you possibly post the code you're trying to use

Michael Taylor - 2/16/07
http://p3net.mvps.org





Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

Perry_R

> I'm not sure what exception you might be getting

Sorry, did I forget to explain that

(And sorry -- this forum edit box seems to force double-spacing, so this may be a pretty ugly response, but I don't seem to have any choice.)

In the first case, using the approach given in one of the MSDN articles, namely indexing the Entries object with an integer like so:

for (int i=log.Entries.Count-1; i>=0; --i) {

EventLogEntry entry = log.EntriesIdea;

if (entry.TimeWritten >= cutoffTime) {

// copy event etc

...

(except the MSDN code counted up, and my code obviously counted down),

the exception is an invalid argument exception in the line like so:

EventLogEntry entry = log.EntriesIdea

********

In the second case, using the other MSDN code sample style,

foreach (EventLogEntry entry in log.Entries) {

if (entry.TimeWritten >= cutoffTime) {

// etc

...

then the exception is again an invalid argument exception, occurring in this line:

foreach (EventLogEntry entry in log.Entries) {

In the first case I can wrap a try catch around the line, eg,

EventLogEntry entry;

if (i > log.Entries.Count-1) return; // event log has changed and our index is out-of-range

try {

entry = log.EntriesIdea;

} catch (Exception exc)

nlog.ErrorException("Event log changed and our index went out-of-range", exc);

return;

}

...

But its kind of tough to put the try catch inside the foreach line itself for the second case

foreach (try { EventLogEntry entry in log.Entries } catch ...

hehe

But, as I was trying to say, the real problem is not so much the bugs with accessing and the foreach and the indexing, but on a larger, logical scale -- how to read a contiguous time span block.

Unfortunately, either it is undocumented or has eluded me, what the actual behavior of EventLog entries is -- is the first entry in the log.Entries array always the oldest Is the first entry returned from the enumerator always the oldest I've been guessing so.

And then, probably as importantly, what happens if the oldest event is overwritten right as one starts to access it, or as one is accessing it

In the meantime, I've run into another logical problem -- it appears that doing this

// (using try-catch wrapper outside for when foreach breaks with invalid argument exception)

foreach (EventLogEntry in remoteLog.Entries) {

...

triggers successful logon events on the remote computer for each access to each EventLogEntry.

This produces a dog chasing its tail scenario -- read one event, and the remote computer logs a successful logon, so there is a new event not yet read, etc -- so reading 20,000 events yields 20,000 new successful logon events still to be read!

Very entertaining -- and hopefully even more entertaining to everybody reading this except me, but not terribly productive :)





Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

TaylorMichaelL

Yes each request to retrieve the entries of a remote log will probably generate a logon attempt. The only workaround would be to catch the exception inside the for-each but depending on the error it might not work.

As for the ordering it does chronological from oldest by default. There is support for reading backwards but I don't see any way of enabling it outside the enumerator itself. As far as reading goes the event log logic goes through a lot of hoops to make sure you don't have problems. Ultimately enumerating through using either a standard for loop or for-each should work whether or not the underlying events change. The only scenario where you should run into problems is if the log was trimmed while you were reading it. This could cause some problems. However having an event overwritten should not cause any problems beyond you not being aware that it had been overwritten. Ultimately this code works just like it is documented that you should use it.

Ultimately I'm wondering if it is a problem with the fact that you're trying to access a remote machine's log and perhaps do not have permission enough to view the log or portions of the log. Does your code work when run against the local log

Michael Taylor - 2/17/07
http://p3net.mvps.org





Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

Perry_R

> Ultimately I'm wondering if it is a problem with the fact that you're trying to access a remote machine's log and perhaps do not have permission enough to view the log or portions of the log.

It is strikingly obvious when the problem is permissions -- an exception is thrown which includes text about permission denied -- so it is very difficult to imagine anyone overlooking that. (I tested that as well, in testing exception handling.)

You say that there should be no problem if the underlying events change, but why you do assert this so confidently -- could you explain -- especially in regards to my particular problem -- which is of course where my interest lies :) -- and my particular problem is reading all events, and not losing 80,000 events because the iterator accidentally gave me the newest (stranding 80,000 events which were older than that).

For example, if the reader assumes that the first event returned from the enumerator is the oldest (as my code is, so to me this is the critical assumption), and the enumerator implementation tries to return the oldest event, but it gets overwritten as it is returned -- an event which proves out to be not at all unlikely AFAICT, and does not require the log to be trimmed, but merely the log to have been full and looping (AFAICT), then the reader gets a very recent event, when it was expecting an old event.

I may not have explained clearly, but the only way I've thought of identifying where I left off reading the event log is by the latest time written, and this depends entirely on getting the events back from oldest to newest, and not getting accidentally given the newest event first (because the event log looped/overwrote the oldest).

I wish there were a better way to identify where we left off last time we read the event log, and not only because of this apparent/possible bugginess in the Entries iterator. However, and surprisingly to me, events do not seem to have any identifiers (primary keys) recorded at all, so I've not yet thought of any way to identify them safely.





Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

TaylorMichaelL

There is no way to guarantee that you are, in fact, getting all the events. Not even the Win32 API every made that guarantee. With event overwriting enabled the event log is a circular buffer. However none of the event logs are set up by default to do this (except after a long period of time). If it is of significant concern that you can not lose any generated events then I would recommend that you ensure the logs are not set up to overwrite data.

What I meant by the underlying events change not being a problem was that internally Windows will ensure that while an event is being written to the log that reads are blocked. Therefore it is not possible for you to run into an error while the event log is being updated. However you might very easily miss an event that you haven't read yet. I believe that the internal event log code (i.e. Windows) uses a moving buffer internally so you should never run into a case where you get event A and then event B and event B is older than event A. However I'd have to test that scenario by writing a Win32 app to call the underlying API and then ensuring that the event log got overwritten. Can you confirm whether this is truly happening or not

There is no mechanism in .NET to get the unique info about an event. The Win32 API does expose the record number of the event which is sequentially incrementing. It is a DWORD so it'd take a while to wrap. I don't believe it resets when the event log is overwritten. Internally in .NET. The enumerator gets the # of the oldest event log record. It then adds the current index (starting at zero) to the record in order to get the event associated with it. Therefore if the record number does not duplicate then the enumerator will never return the same value. However if the oldest record value changes (because of overwriting) then it is possible that you could very well get an exception from the event log because you'd be trying to access an event that no longer exists. However given the size of the event log and the presumed speed of your code this seems like a highly unlikely event. I guess you could get into a scenario where the event log became full while you were enumerating but events would have to be added to the log faster than you can read them back out. It seems like a boundary case that you are trying to handle in code while the real problem is why it is getting full so fast to begin with. Just my opinion.

If you truly want to try and handle this case then you can either use CopyTo that I mentioned in my first post to try and circumvent (but not prevent) this possibility. Alternatively you can move to P/Invoke and just handle the Win32 errors that will occur. Irrelevant you'll have to programmatically handle this possibility if it is going to be a show stopper for you. Perhaps someone from MS can provide better insight into how you can handle this case.

Michael Taylor - 2/18/07
http://p3net.mvps.org





Re: .NET Base Class Library EventLog errors due to events being written whilst I'm reading them

Perry_R

When you return to statements like this:

>then it is possible that you could very well get an exception from the event log because you'd be trying to access an event that no longer exists. However given the size of the event log and the presumed speed of your code this seems like a highly unlikely event.

it makes me suspect we have a miscommunication -- but I'm not sure if I'm missing something or you are, or we both are.

You talk about default event logs being set up not to overwrite, and that it is "highly unlikely" that the event log fills up and overwrites.

I'm not sure if I'm misunderstanding scenarios, or oversimplifying or undersimplifying or what, but I'm not talking about a small system which has just had Windows installed and has few events and lots of free space in the event logs. I'm talking about many long-running systems, which are constantly overwriting their old events -- all the time. They are sufficiently long-running that they are almost all running at event log capacity, so their new events are always overwriting their old events.

So, to me it seems extremely likely that if Windows looks for the oldest event record and passes it to me to read, that it will be overwritten very quickly -- I mean, isn't that *the very record* that is about to be overwritten at any second I mean, I assume that this is a conventional circular buffer, in which it is the oldest record which will be overwritten next.

For that reason, instead of a highly unlikely scenario, this seems to me a highly likely one. Therefore I am not all that surprised that I have found this apparent bug in the Entries iterator -- I mean, it seems to me that as soon as one starts running against real, production servers, one will immediately find this scenario to be likely and commonplace