Why do inotify events fire more than once

Question

This question arises from another one that I had posed on Stackoverflow. I am using Watcher - the same issues apply to Incron - to monitor a folder and its child folders for changes and silently squirrel away those changes to Dropbox.

I monitor the write_close event - IN_CLOSE_WRITE - for the purpose. Originally I was watching the modify event, i.e. IN_MODIFY. While this worked I found that when writing large files it would fire more than once. That sounded fair so I switched to IN_CLOSE_WRITE since I felt that it was reasonably fair to assume that for a given file it would only occur once.

However, that is not the case. Even for a very small text file - just one character - created in Nano the event occurs two times. At best this can result in unnecessary traffic when the same file is synchronized on Dropbox two times. In my own case it leads to disaster since on the first event I perform the synchronization and then delete the server side file. The result - on the second event the Dropbox side file becomes a 0 byte file.

I am dealing with this for now by making my synchronization script sleep for 10s before I do anything else and then I check that the file in question still exists prior to attempting Dropbox sync. This works because on the second iteration the file is missing and the script just terminates.

This sounds hackish at best. Perhaps not a bad hack but I would prefer to understand - just why does even the IN_CLOSE_WRITE event occur more than one time?

---

Some additional information

• Check to ensure that there aren't multiple instances of watcher running.

Output from ps ax|grep watcher.py

23880 ?        Sl     0:01 python /usr/local/bin/watcher.py restart
24977 pts/0    S+     0:00 grep --color=auto watcher.py

The file system is ext4. I should mention that I have encountered precisely the same issue with Incron. I start the Watcher daemon up from a batch script executed via /etc/rc2.d. Incron OTH starts up without any messing about by me via its default apt-get install incron installation.

---

The essence of my watcher.ini file is shown below.

[DEFAULT]
logfile=/var/log/watcher.log
pidfile=/var/run/watcher.pid

[job1]
watch=/path/to/watch

events=write_close
excluded=
recursive=true
autoadd=true

command=/home/datastore.php $filename

I reduced the datastore.php script to the bare essentials to verify that it is fired up twice without any of my messy Dropbox upload + source delete code.

#! /usr/bin/php
<?php
file_put_contents('/tmp/watcher',$argv[1],FILE_APPEND);

?>

I then created a little file at the path in question and then examined /tmp/watcher. The problem still persists - the file still has two successive entries for $argv[1].

Answer 1

I've just had this using IN_CLOSE_WRITE and finally tracked down the problem. My original script was reading in mail from stdin line by line and then writing each line to the file. This was causing incron to fire on every line write. I saw this based on the number of incron events and how many lines were in the file.

I then changed the original script to read all of stdin in before writing the file. Once this was in place I no longer saw multiple incron executions on the same file.

Answer 2

I don't have enough rep to post this as a comment, but are you sure that temporary, possibly-hidden files are not being created? I had a similar issue with inotifywait firing multiple times, but I realized it was because vim would create a .swp file when editing, which would fire an event when closing. It would also pick up the close event from the original file.

It sounds like you're noticing the event firing multiple files on the same file though, which is not something I've been able to reproduce -- this would only happen once for the temp file and once for the original.

I tried a quick test with nano and I don't think it creates a temp file at all (at least for the few character case), but is there anything else in your setup that could rely on similar behavior?

Answer 3

I am not sure, but most probably the first write_close writes file attributes into it, like creation time, and only after that it writes actual data. In fact rsync creates a temp file and when everything is done it moves the temp file to the actual file in the same folder so it is easy to monitor has been normally created in when you use rsync, and move is an atomic operation. On the other hand there is something calle one shot in inotify, probably that using that we can trigger something on the first modify message, and as you suggested sleep for reasonable amount of time before starting the operation. I am digging this now, and will update when I find anything new. https://superuser.com/questions/1133642/traceing-the-moment-when-file-is-completely-copied-to-samba-share-with-inotify

Answer 4

I notice that i get 2 events if i use > or cp:

root@vm-dvde05:~# touch file
root@vm-dvde05:~# inotifywait --recursive --monitor --event modify file &
[1] 31835
root@vm-dvde05:~# Setting up watches.  Beware: since -r was given, this may take a while!
Watches established.

root@vm-dvde05:~# echo string>file
file MODIFY
file MODIFY
root@vm-dvde05:~# cat file
string
root@vm-dvde05:~# cp /etc/hosts file
file MODIFY
file MODIFY
root@vm-dvde05:~#

But if i use append >> it shows single event:

root@vm-dvde05:~# echo string2>>file
file MODIFY
root@vm-dvde05:~# kill %1
root@vm-dvde05:~#
[1]+  Terminated              inotifywait --recursive --monitor --event modify file
root@vm-dvde05:~#

To get single event i monitor CLOSE_WRITE