Test piece to track a log file.

[hutch--]

A friend of mine who lives up the road asked me about a UNIX utility called TAIL. I gave him a copy of the set of command line unix utilities I have but also had a go at a GUI based logger. After a lot of trial and error, I have got a test piece that will run a timer based check if the log file has been modified and will read and display the last 4096 bytes if it has.

I have it working but I class it as slow, it seems to be happy enough at a 1 second interval but is too slow to run much faster than that. The test piece is accompanied by another test piece called LOG.EXE which simply opens a file and keeps appending data to it from a timer based interval. The log tracker TRAKLOG.EXE if you open the file that is being written by LOG.EXE which is TEST.LOG will read the last 4k of it every second if its changing and display the contents.

I know this type of stuff must have been done before and I wondered if anyone has either worked on an app of this type or written tools that log the tail end of a file. From running the unix TAIL, it seems to be picking up the input stream to the log file as it continuously updated as data is added to the log file.

[attachment deleted by admin]

[PBrennick]

Hutch,
You have set it up so that the logfile starts over after 10000 lines.  Is this just an arbitrary thing used in the test piece or is there a buffer limtation?

It is pretty cool watching the logfile in realtime.

Paul

[Ossa]

Rather than polling, might it not be better to use the FindFirstChangeNotification procedure, with a wait of some sort? The only problem that I can see would be if the change notifications came in too often, it might cause issues.

Ossa

[PBrennick]

Personally, I would NEVER change code that is running with no problems in all situations to code that 'might' have issues from time to time.  Just does not sound like a good trade-off.

Paul

[Ossa]

True, however, if written properly it would not have such issues - the difficulty in getting it to that state is due to the added complexity of the waiting. Naturally, you should always back up the (source code of the) working version, so that if the attempt to alter it doesn't work, you havn't lost anything but time.

What I meant by "might cause issues" is dependent on how often windows sends such messages. In order to combat this you could (and I'm sure that there are many, many better solutions) use a second thread that waits for the change notifications, filters out the irrelvent ones and has some limiting in built, such that the GUI will not go out of control trying to deal with the new data coming from the file.


Thread 1 (Main):
- GUI update, etc

Thread 2 (Worker):
- Waits for file change and timer events
- If change event occurs:
   + check if it is for the correct file
   + check if the change is significant,
     * if yes, update now and reset timer
     * else, flag that a past event has occurred without action
   + go back to wait
- If timer event has occurred
   + check if the no action taken flag is set
   + if so, update now


As you can see, it is fairly complex. I would choose this method though.

Ossa

[hutch--]

What I was hoping for was someone who ran a server that used a log file had the time to either test it or who knew what was normally used as an external program to do this task. The unix TAIL does the job but it seems to be accessing the data differently as it appears to be a stream rather than a timer interval.

[PBrennick]

Yeah, well, sorry, Hutch.  My network is serverless.  It is just a ring of interacting nodes.

Paul

[farrier]

hutch--,

I don't have a server with a log file either,  but as a response to the suggestion from Ossa, look at a program which seems to work well detecting a file change.  Gives a notification on file creation, deletion, renaming, modification, copying/moving.  Writen in FASM.  FC.zip:

http://board.flatassembler.net/topic.php?t=4835

hutch--, if you haven't already, register at the FASM board if only to monitor what f0dder has to say.

farrier

[zcoder]

I use FindFirstChangeNotification to create an obj of what I want to monitor
then I create a thread with  WaitForMultipleObjects then in that thread
I make it send the message to the main app that a change has happened.

Here is how small the thread is:

Code Select Expand



LogWatch proc hWin:DWORD

@@:
        mov eax,offset ObjArray
        invoke WaitForMultipleObjects,20,eax,FALSE,INFINITE
        invoke SendMessage,hWin,WC_WINDOWCHANGE,eax,eax
        invoke FindNextChangeNotification,ObjArray.hWinChangeFileName
       .if StopLogWatch == 1     
           ret
       .endif
      jmp @B

LogWatch endp



the above is just a section of a multy watch that resets the one that fired. and resets it again after informing the main app of the change.
This works fine on my Apache server to monitor the log file.

Zcoder....

[MichaelW]

The attachment includes a small console app that uses ReadDirectoryChangesW to monitor for changes in test.log. It is the file buffering that is slowing everything down. Before I modified log.asm, synchronous calls to ReadDirectoryChangesW would return not more frequently that about once every second, and sometimes not for much longer. After I added a call to FlushFileBuffers following the call to fprint, ReadDirectoryChangesW returned after each update of test.log. I initially thought that asynchronous operation and a completion routine would be required to get the % processor time for the monitoring app down to something reasonable, but as it is currently coded, with synchronous calls to ReadDirectoryChangesW, the % processor time stays at or very close to zero.

EDIT: Corrected a problem with the attached source where I defined a buffer instead of a pointer to a buffer (Windows actually allocates the buffer).


[attachment deleted by admin]

[hutch--]

I tried Michael's suggestion and it made the results a lot faster but the catch is with someone elses server application, I have no access at how it writes its log file.

I thought there may have been a way to catch the data stream as it was being written but I have not seen anything that does that at the moment. With Michael's mod, I set the interval in the tracker to 100 ms and it seemed to be running OK and the processor usage barely changed from the normal.

[farrier]

hutch-- & MichaelW,

The app I pointed to uses the same ReadDirectoryChangesW as MichaelW in a separate thread constantly monitoring for file change.  The app/thread shows little cpu usage.  The app will monitor a directory for changes and report the name of the changed file and what the change was: create, modify, delete, move, ...  It might be what you can use.  Hope so.

farrier

[hutch--]

farrier,

I had a look at you code and it looks fine but my problem is not the monitoring, its the file access to the log being written by a Microsoft server. I just sent my friend the latest version and File Monitor still reports access violation so I am still at square one just to get it to work.

PS: I have been a member of Tomasz's forum since it started, I just don't get much time to scan what gets posted there but to be honest, I would rather sleep in than waste my effort tracking the postings of a particular person whose name I will not mention here.  :bg

[farrier]

hutch--,

I think I finally understand!  When working on the backup routine that led to the fc.exe program in my link, I initially used FindFirstChangeNotification.  When my program received the notification, I would immediately try to copy the file in question.  Sometimes it worked and sometimes it didn't.  It turned out to be the file was still open and being added to by the main applications archiving routine.  So I put in a loop, trying to open the file with CreateFile, if the return value was INVALID_HANDLE_VALUE, I checked GetLastError, and if the return value was 32 or 33--ERROR_SHARING_VIOLATION or ERROR_LOCK_VIOLATION--I looped until I could open the file.  Then copy the file to the backup disk.  Maybe this is what is happening to you?  What kind of error do you get?  Can you ever open the file?

Aother humble suggestion: Say the filesize was 2,456,345 bytes the last time you checked the file, after successfully opening the file, if the file size has increased, set the file pointer to this location and read/copy the rest of the file to another buffer, close the log file and then check the buffer for whatever you're looking for.  This might decrease the time that you have the log file opened.

Using my routine in a separate thread with the never ending loop, you don't have to set a timer, and you only have to wait for the FILE_NOTIFY_CHANGE to trigger.

hth,

farrier

[hutch--]

The file I am testing on is the one my friend is testing it on which is WindowsUpdate.log in the winnt directory of win2000. This one is not even being written to but the system error string from GetLastError is "The process cannot access the file because it is being used by another process."

The interesting part is the unix utility TAIL can read it. I looked up its imports and its plain MSVCRT functionality but I don't know how its getting the file read access.

I have attached the version of TAIL that does work performing this task.

[attachment deleted by admin]