question to FOLDERMONITOR

#1
I want to create a Foldermonitor to copy all new/changed files from the monitored folder to a different location. Example:
Code:
c:\program files\jpsoft\tcmd14x64>ver
 
TCC  14.00.30 x64  Windows 7 [Version 6.1.7601]
 
c:\program files\jpsoft\tcmd14x64>foldermonitor
No folders/files are being monitored.
 
c:\program files\jpsoft\tcmd14x64>foldermonitor d:\temp\foldermonitor created modified forever copy "%%_foldername\%%_folderfile1" "c:\temp\foldermonitor"
 
c:\program files\jpsoft\tcmd14x64>foldermonitor
d:\temp\foldermonitor  created modified  (0/FOREVER)  copy "%_foldername\%_folderfile1" "c:\temp\foldermonitor"
At this point I copy 10 files with a filemanager to d:\temp and this is what happens:
Code:
c:\program files\jpsoft\tcmd14x64>D:\temp\foldermonitor\KB2656368v2_20120613_182329222.html => C:\temp\foldermonitor\KB2656368v2_20120613_182329222.html
    1 file copied
Oops.
I expected that all files are handled but not only 1 of them.
Did I misunderstand the approach of FOLDERMONITOR or did I do something wrong?
The doc is not very comprehensive.
 
#2
Rex explained FOLDERMONITOR here: http://jpsoft.com/forums/threads/foldermonitor-missing-events.2933/.

My 4THREADS plugin contains WATCHDIR which does queue events and processes the queue in a separate thread. It has no problem capturing 172 events in 5 seconds (when I build a project) or even 3000 events in 3 seconds ...
Code:
v:\> watchdir twatch t:\
v:\> do i=1 to 1000 ( touch /c /q t:\%i.txt & del /q t:\%i.txt )
00:19:35.106  CREATE  1.txt
00:19:35.106  MODIFY  1.txt
00:19:35.106  DELETE  1.txt
*SNIP*
00:19:37.649  CREATE  1000.txt
00:19:37.649  MODIFY  1000.txt
00:19:37.649  DELETE  1000.txt
A variable whose name matches the watch ID is available during any command. Keep in mind that commands executed by WATCHDIR happen in a separate thread which has no idea what else TCC may be doing at the moment. I don't think WATCHDIR has had much of a workout; comments would be appreciated.
 
#3
Thank you, Vince.
I will occupy with it the next days.
Tomorrow is my 1st workday after 2 weeks of staycation :(
 
#4
Vince,

can you please explain me the "/E command" parameter?

A first try gives me an odd number of lines in the logfile
(or could it be even more crowded if I copy very big files which take longer to copy?):

Code:
(system)  C:\...\TCMD14x64 >watchdir /k
 
(system)  C:\...\TCMD14x64 >watchdir wd1 d:\temp\foldermonitor /l
 
(system)  C:\...\TCMD14x64 >watchdir /l
Id      wd1
Dir    d:\temp\foldermonitor
Started 2012-10-09 22:10:54
Status  ACTIVE
Filters FDZW
Found  0
Skipped 0
Total  0
Limit  0
Log    C:\Program Files\JPSoft\TCMD14x64\wd1.log
Command None
 
(system)  C:\...\TCMD14x64 >dir d:\temp\foldermonitor\
 
Volume in drive D is d2_p1          Serial number is ee7b:f5b6
Directory of  D:\temp\foldermonitor\*
 
09.10.2012  22:09        <DIR>    .
09.10.2012  22:09        <DIR>    ..
                0 bytes in 0 files and 2 dirs
    55.934.029.824 bytes free
 
(system)  C:\...\TCMD14x64 >copy d:\temp\*.html d:\temp\foldermonitor\
D:\temp\KB2600217_20120327_221251720.html => D:\temp\foldermonitor\KB2600217_20120327_221251720.html
D:\temp\KB2604121_20120509_224118559.html => D:\temp\foldermonitor\KB2604121_20120509_224118559.html
D:\temp\KB2656368v2_20120613_182329222.html => D:\temp\foldermonitor\KB2656368v2_20120613_182329222.html
D:\temp\KB2656368_20120413_222805602.html => D:\temp\foldermonitor\KB2656368_20120413_222805602.html
D:\temp\KB2656405_20120509_224403560.html => D:\temp\foldermonitor\KB2656405_20120509_224403560.html
D:\temp\KB2686827_20120613_181939717.html => D:\temp\foldermonitor\KB2686827_20120613_181939717.html
    6 files copied
 
(system)  C:\...\TCMD14x64 >type /l wd1.log
  1 : 22:11:41.460  CREATE  KB2600217_20120327_221251720.html
  2 : 22:11:41.460  MODIFY  KB2600217_20120327_221251720.html
  3 : 22:11:41.460  MODIFY  KB2600217_20120327_221251720.html
  4 : 22:11:41.460  MODIFY  KB2600217_20120327_221251720.html
  5 : 22:11:41.460  CREATE  KB2604121_20120509_224118559.html
  6 : 22:11:41.460  MODIFY  KB2604121_20120509_224118559.html
  7 : 22:11:41.460  MODIFY  KB2604121_20120509_224118559.html
  8 : 22:11:41.460  CREATE  KB2656368v2_20120613_182329222.html
  9 : 22:11:41.460  MODIFY  KB2656368v2_20120613_182329222.html
  10 : 22:11:41.460  MODIFY  KB2656368v2_20120613_182329222.html
  11 : 22:11:41.460  CREATE  KB2656368_20120413_222805602.html
  12 : 22:11:41.460  MODIFY  KB2656368_20120413_222805602.html
  13 : 22:11:41.460  MODIFY  KB2656368_20120413_222805602.html
  14 : 22:11:41.460  CREATE  KB2656405_20120509_224403560.html
  15 : 22:11:41.460  MODIFY  KB2656405_20120509_224403560.html
  16 : 22:11:41.460  MODIFY  KB2656405_20120509_224403560.html
  17 : 22:11:41.460  CREATE  KB2686827_20120613_181939717.html
  18 : 22:11:41.460  MODIFY  KB2686827_20120613_181939717.html
  19 : 22:11:41.460  MODIFY  KB2686827_20120613_181939717.html
 
#5
Vince,

can you please explain me the "/E command" parameter?

A first try gives me an odd number of lines in the logfile
(or could it be even more crowded if I copy very big files which take longer to copy?):
Apparently, the COPY causes four events per file, one CREATE and three MODIFY events. I don't know exactly why that is; it just seems to be how the underlying API (CopyFile, perhaps) works. With command line args you can filter only the events you want reported.

"/E command" runs a command for each event. While that command is running an environment variable with the name of the watch ID exists and has, as value, the log line for that event. So you can take it apart with @WORD. For example (I'll watch the temp dir during a build).
Code:
v:\> watchdir twatch t:\ /e echo file: %%@word[2,%%twatch]
 
v:\> file: bb5b697df2d6453497373d340fe55cc8.tmp
file: bb5b697df2d6453497373d340fe55cc8.tmp
file: bb5b697df2d6453497373d340fe55cc8.tmp
file: 11673392439f41c1a6a58d921b325cf9.rsp
**SNIP**
Here's another:
Code:
v:\> watchdir twatch t:\ /e echo logline: %%twatch
 
v:\> logline: 16:46:51.360  CREATE  06577792cb7e4ac69c144879ec66849b.exec.cmd
logline: 16:46:51.360  MODIFY  06577792cb7e4ac69c144879ec66849b.exec.cmd
logline: 16:46:51.360  MODIFY  06577792cb7e4ac69c144879ec66849b.exec.cmd
logline: 16:46:51.532  CREATE  EXEFF8C.tmp
logline: 16:46:51.563  MODIFY  EXEFF8C.tmp
**SNIP**
 
#6
P.S. If I rebuild the plugin I can specify that it use microseconds for timestamps. This shows that the three MODIFY events logged with a file is copied are, indeed, separate events.
Code:
v:\> watchdir twatch t:\ /e echo %%twatch
 
v:\> copy /q avetemp.txt t:\
16:57:38.025451  CREATE  avetemp.txt
16:57:38.025635  MODIFY  avetemp.txt
16:57:38.025736  MODIFY  avetemp.txt
16:57:38.025868  MODIFY  avetemp.txt
 
#7
Vince: I suggest you write a simple compiled program which records the time and action of each file related API call, i.e., open/create, write, close. Matching the times reported by the program with those reported by WATCHDIR could explain why multiple modify events are reported by COPY.
 
#8
Vince: I suggest you write a simple compiled program which records the time and action of each file related API call, i.e., open/create, write, close. Matching the times reported by the program with those reported by WATCHDIR could explain why multiple modify events are reported by COPY.
I don't know what further APIs are called by CopyFile() (which is what I suppose TCC is using). And I don't know how to find out, or (even if I knew) how to find out when they were called ... short of writing a debugger (which is a bit beyond my expertise). If I get the time, I'll step through "COPY file destination" with WinDbg to see what's going on. I'm satisfied with "that's just the way it works". Who knows what Windows in doing ... no doubt altering the contents of the file but also setting ownership and perhaps other security-related things (all of which could qualify as a MODIFY event).
 
#9
I don't know what further APIs are called by CopyFile() (which is what I suppose TCC is using). And I don't know how to find out, or (even if I knew) how to find out when they were called ... short of writing a debugger (which is a bit beyond my expertise). If I get the time, I'll step through "COPY file destination" with WinDbg to see what's going on. I'm satisfied with "that's just the way it works". Who knows what Windows in doing ... no doubt altering the contents of the file but also setting ownership and perhaps other security-related things (all of which could qualify as a MODIFY event).
Windows also has to set the file's times (another MODIFY perhaps).

... just tried it ... security-related events **are** reported an MODIFY events
 
#10
I agree on the "who knows..." and I do know that at least some Unix/clone systems consider (wrongly, IMHO) modifying a file attribute as "modifying the file". Personally I consider "file modification" to refer exclusively to file content. However, there is a difference between a "modification event" and "file modification", and attribute modification could legitimately be considered a "modification event". I used the word attribute above in its generic sense, including ownership, access rights, time stamps, size, etc.
 
#11
The only distinctions I can make are these. So secutiry/time-related changes are simply MODIFY events.

FILE_ACTION_ADDED
0x00000001
The file was added to the directory.
FILE_ACTION_REMOVED
0x00000002
The file was removed from the directory.
FILE_ACTION_MODIFIED
0x00000003
The file was modified. This can be a change in the time stamp or attributes.
FILE_ACTION_RENAMED_OLD_NAME
0x00000004
The file was renamed and this is the old name.
FILE_ACTION_RENAMED_NEW_NAME
0x00000005
The file was renamed and this is the new name.
 
#13
#14
When I copy a file, watching the destination directory for only /+WA (write/access times) I get only one MODIFY event. If I watch for only /+T (attributes) I get three MODIFY events. If I watch for only /+Z (size) I get two MODIFY events. There are some clues to what's going on and also an indication that Windows may be combining events (since watching for everything yields only three MODIFY events).