Friday, June 24, 2011

Log file monitoring pain points

In SCOM you do have the possibility to monitor log files in case that your application is not writing into the Windows Event Log what should be the preferred way.
Unfortunately there are some points that you have to be aware of:
  1. Do not clear the log file!
  2. If using the same log file watch out for the size!
  3. If using rotating log files be sure that the actual file name will always change!

Regarding point 1:

Operations Manager will remember the last checked line within your log file. So in case that was in line 100, SCOM will start reading in line 101 the next time the workflow runs. If you decide to clear the log file and start filling it from line 1, SCOM will not proceed until line 101 is reached.

Regarding point 2:

If you use the same log file it would be a good idea to monitor the file size and alert at a useful threshold so that your volume will not run out of space. But: what to do when that becomes true? See point 1 and 3!

Regarding point 3:

This one is really strange! (until you understand http://support.microsoft.com/kb/172190 (thx to Chris for his comment)

If you use rotating log files to be sure that you have for instance a new one for each day/week/… or a new one when a file size has been reached – what is a very good approach at all – it is very often, that the current log file has a fixed name like myapp_current.log and the archived log files a name like myapp_<date>_<time>.log or something similar.
Most of the time the log writing application renames the current log to one including date and timestamp in the name and after that, a new one will be created. So far, so good and SCOM can read the new log file if the created timestamp is newer than from the file with the same name before. But…
Unfortunately NTFS is not as smart as it looks like: in case you delete a file called test.txt and create a new one with the same name within the minute you have deleted the old one, the created timestamp will be the one from the old one and not from the one newly created and SCOM will treat it like a cleared file as in point 1.
You can test that easily on your client:
  1. Create a new file called test.txt in a temporary folder.
  2. Check the created timestamp.
  3. Wait until the current time has changed at least to the next minute.
  4. Delete the file created in step 1.
  5. Create a new file and call it test.txt too. Be sure that you do that within the same minute as you deleted the first file in step 4!
  6. Check the created timestamp and verify that it is the same as you've noticed in step 2.
So the NTFS meta data is not up-to-date.
OK, now we try something different:
  1. Use the file created in step 5 of the sample above or create a new file called test.txt in a temporary folder.
  2. Check the created timestamp.
  3. Wait until the current time has changed at least to the next minute.
  4. Delete the file created in step 1.
  5. Wait again until the current time has changed at least to the next minute.
  6. Create a new file and call it test.txt too.
  7. Check the created timestamp and verify that it is a different one as you've noticed in step 2.
Lesson learned: it seems that NTFS meta data will be updated every minute. My experience in my tests was, that this will be done every full minute but it is possible that this happened just by accident. Anyway…
The problem is that in most of the cases you are not able to define, when the new log file should be created after the rotation. So you are also not able to handle that kind of behavior.
The only workaround (well, it is more a solution than a workaround) is to use the date and timestamp in the current log file too and create your workflow with wildcards for that variables. So if your log file name looks like myapp_<date>_<time>.log you can create the workflow to watch out for myapp_*_*.log . SCOM will only touch files that have been modified since the last run.
Here are some other thoughts from Anders Bengtsson (thanks, Anders!) regarding log file monitoring.
All information is provided "as is" without any warranty! Try in lab before. Handle with care in production.

6 comments:

  1. Check http://support.microsoft.com/kb/172190 for #3

    Thanks,
    Steve Ch.

    ReplyDelete
  2. Great article, thanks Steve!

    ReplyDelete
  3. Nice article appreciate it.

    ReplyDelete
  4. Is it possible to monitor a log file that gets created each day but is in a new folder. I have a scenario where the folder the log is created is new each day with the date stamp. The actual log file name never changes

    ReplyDelete
    Replies
    1. Same issue here. Did you find some sort of solution?

      Delete
    2. Same here...would be good to know if this can be done without the need to script it

      Delete