linux-kernel - PROBLEM: 2.6.35.7 Inotify events missing

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <20101018223540.GA20730@gradator.net>
Date:	Tue, 19 Oct 2010 00:35:40 +0200
From:	Sylvain Rochet <gradator@...dator.net>
To:	linux-kernel@...r.kernel.org
Subject: PROBLEM: 2.6.35.7 Inotify events missing

Hi,

I write a tool that keep in sync one source (master) to multiple 
targets (slaves) to provide always up to date mirrors in order to 
distribute static content at different locations.

That was working fine on 2.6.26.5 kernel, except bugs that are my 
fault and which are fixed the way the time goes.

A day I upgraded to 2.6.33.5, then 2.6.33.7, finally to 2.6.35.7, and I 
always end up with the same ending, it seems inotify can miss some VFS 
events from time to time.

I wrote a simple tool which is a cleaned code of the first 
explained master process that only display received inotify events and 
with the recursion stuff that keep all directories watched.


First, this is not due to queue limit depth, limits are way over 
requirements. I don't received IN_Q_OVERFLOW event either.

$ cat /proc/sys/fs/inotify/max_{queued_events,user_instances,user_watches}
524288
128
1000000


That may help, files and FS tree are modified over NFS.


Here is what I got:

# stat ./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.xhtml
  File: `./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.xhtml'
  Size: 11696           Blocks: 24         IO Block: 4096   regular file
Device: 90ah/2314d      Inode: 144835214   Links: 1
Access: (0644/-rw-r--r--)  Uid: (20981/ UNKNOWN)   Gid: (26734/ UNKNOWN)
Access: 2010-03-18 14:04:59.000000000 +0000
Modify: 2010-10-14 06:44:27.000000000 +0000
Change: 2010-10-14 06:44:27.000000000 +0000

# stat ./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.i
  File: `./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.i'
  Size: 30575           Blocks: 64         IO Block: 4096   regular file
Device: 90ah/2314d      Inode: 144835393   Links: 1
Access: (0644/-rw-r--r--)  Uid: (20981/ UNKNOWN)   Gid: (26734/ UNKNOWN)
Access: 2010-03-18 14:04:59.000000000 +0000
Modify: 2010-10-14 06:44:26.000000000 +0000
Change: 2010-10-14 06:44:26.000000000 +0000

So, here is two files that were modified at about 2010-10-14 06:44:26.

And now is what I got in the event log of my inotify logger:

# grep db303d42803e58bb5f73467291c9a863 debugevents 
2010/10/12 20:06:48 1286914008:604497: wd=16623 mask=2 cookie=0 len=48 name=db303d42803e58bb5f73467291c9a863.i pathname=./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.i
2010/10/12 20:06:48 1286914008:605215: wd=16623 mask=2 cookie=0 len=48 name=db303d42803e58bb5f73467291c9a863.i pathname=./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.i
2010/10/12 20:06:48 1286914008:686793: wd=16623 mask=2 cookie=0 len=48 name=db303d42803e58bb5f73467291c9a863.xhtml pathname=./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.xhtml
2010/10/12 20:06:48 1286914008:687372: wd=16623 mask=2 cookie=0 len=48 name=db303d42803e58bb5f73467291c9a863.xhtml pathname=./xnlegacies/statique/wiki/cache/d/db303d42803e58bb5f73467291c9a863.xhtml

I did not receive events about the modification of those files at 
2010-10-14 06:44, but we received previous events 2 days ago



Here is another example:

# stat ./synfig/forums/files/thumb_5_ec61d61306649e73f2549775c2ee3e1c   
  File: `./synfig/forums/files/thumb_5_ec61d61306649e73f2549775c2ee3e1c'
  Size: 23886           Blocks: 48         IO Block: 4096   regular file
Device: 90ah/2314d      Inode: 178390723   Links: 1
Access: (0664/-rw-rw-r--)  Uid: (15653/ UNKNOWN)   Gid: (27452/ UNKNOWN)
Access: 2010-10-15 05:28:35.000000000 +0000
Modify: 2010-10-15 05:28:35.000000000 +0000
Change: 2010-10-15 05:28:35.000000000 +0000

Here is a file that was modified at 05:28:35.


# grep thumb_5_ec61d61306649e73f2549775c2ee3e1c debugevents 
2010/10/15 05:28:35 1287120515:058819: wd=16079 mask=100 cookie=0 len=48 name=thumb_5_ec61d61306649e73f2549775c2ee3e1c pathname=./synfig/forums/files/thumb_5_ec61d61306649e73f2549775c2ee3e1c

I received an event that the file was created, at the time of the event 
the file was 0 byte length, the file was then filled, but we did not 
received events about the fact that the file was modified.


If I try to do the same, I get IN_CREATE, then IN_MODIFY,

# echo "test" > hFq0gUrK1EGwoT2pnpCO

# grep hFq0gUrK1EGwoT2pnpCO debugevents 
2010/10/18 19:40:59 1287430859:712722: wd=1 mask=100 cookie=0 len=32 name=hFq0gUrK1EGwoT2pnpCO pathname=./hFq0gUrK1EGwoT2pnpCO
2010/10/18 19:40:59 1287430859:713543: wd=1 mask=2 cookie=0 len=32 name=hFq0gUrK1EGwoT2pnpCO pathname=./hFq0gUrK1EGwoT2pnpCO



I attached my quick-n-dirty inotify logger. Source code of the full 
replication software is available here[1], if it helps.


I can provide as many information as possible and I am willing to do so ;)

Regards,
Sylvain



[1] svn://svn.tuxfamily.org/svnroot/vhffs4/vhffs/trunk/vhffs-fssync/

View attachment "vhffsfssync_log.c" of type "text/x-csrc" (19019 bytes)

Download attachment "signature.asc" of type "application/pgp-signature" (198 bytes)