inotifywait shows different number of MODIFY events on the same writing operation

[meow-watermelon]

Describe the bug
I noticed the inotifywait reports different number of MODIFY events when writing to the same file.

To Reproduce
Steps to reproduce the behavior:
Open one terminal and run:

while true; do echo -e 'aaaa\nbbbbb\nccccc\n\n\n' > text; sleep 1; done

Open another terminal and run:

inotifywait -m -e modify --format '%T' --timefmt '%a, %d %b %Y %T %z' text

Expected behavior
I should expect I can see the same number of MODIFY events in each cycle.

Screenshots

Sun, 21 Jun 2020 21:41:34 -0700
Sun, 21 Jun 2020 21:41:36 -0700
Sun, 21 Jun 2020 21:41:36 -0700
Sun, 21 Jun 2020 21:41:38 -0700
Sun, 21 Jun 2020 21:41:38 -0700
Sun, 21 Jun 2020 21:41:40 -0700
Sun, 21 Jun 2020 21:41:42 -0700
Sun, 21 Jun 2020 21:41:44 -0700
Sun, 21 Jun 2020 21:41:44 -0700

OS: Fedora 31
Kernel Version: 5.6.18-200.fc31.x86_64
Package Version: inotify-tools-3.14-18.fc31.x86_64

Thanks.

[meow-watermelon]

maybe it's due to the file is not opened by O_DIRECT? strace shows the file is opened by O_WRONLY|O_CREAT|O_TRUNC flag.

[ericcurtin]

I'll tell you what I'm seeing

OS: xubuntu 20.04
Kernel Version: 5.4.0-37-generic
Package version: inotify-tools-3.20.2.2 (the latest master code)

rm ../text; touch ../text; ../src/.libs/inotifywait -m -e modify --format '%T' --timefmt '%a, %d %b %Y %T %z' ../text
Setting up watches.
Watches established.
Mon, 22 Jun 2020 10:29:52 +0100
Mon, 22 Jun 2020 10:29:52 +0100
Mon, 22 Jun 2020 10:29:53 +0100
Mon, 22 Jun 2020 10:29:53 +0100
Mon, 22 Jun 2020 10:29:54 +0100
Mon, 22 Jun 2020 10:29:54 +0100

and the corresponding strace:

strace -e trace=openat,write bash -c "while true; do printf aaaa\nbbbbb\nccccc\n\n\n > text; sleep 1; done"
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/dev/tty", O_RDWR|O_NONBLOCK) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3
openat(AT_FDCWD, "text", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(1, "aaaanbbbbbncccccnnn", 19)     = 19
openat(AT_FDCWD, "/lib/terminfo/x/xterm-256color", O_RDONLY) = 3
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=26086, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
openat(AT_FDCWD, "text", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(1, "aaaanbbbbbncccccnnn", 19)     = 19
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=26087, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
openat(AT_FDCWD, "text", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(1, "aaaanbbbbbncccccnnn", 19)     = 19

this all looks ok on my machine. Could you try the latest version of the code @meow-watermelon ?

I recommend putting strace watching the whole while loop just to be sure you are catching everything.

Then we can start chasing things like kernel version, filesystem type, etc.

Often a good way to start is write a test in here:

https://github.com/inotify-tools/inotify-tools/tree/master/t

that detects this difference, so you can quickly identify on which platforms this difference occurs.

[meow-watermelon]

Hi @ericcurtin, thanks for your reply. But I think what I did is kinda different than what you did. I'm using echo -e to print \n in that case so I would see more modify events.

The strace output:

--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9154, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
openat(AT_FDCWD, "text", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
write(1, "aaaa\n", 5)                   = 5
write(1, "bbbbb\n", 6)                  = 6
write(1, "ccccc\n", 6)                  = 6
write(1, "\n", 1)                       = 1
write(1, "\n", 1)                       = 1
write(1, "\n", 1)                       = 1

inotifywait output:

Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:21 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700
Tue, 23 Jun 2020 22:12:22 -0700

So once I'm using bash -c to call the echo this will show the same number of MODIFY events. But I still have a question here, why there are 7 modify events? But there are 6 write() calls.

Thanks.

[ericcurtin]

Yeah I used printf over echo -e just to use another similar tool to see if it changed the write behavior. What's interesting is when I use echo -e on my machine it is one single write when redirected to file:

write(1, "aaaanbbbbbncccccnnn\n", 20) = 20

But yours is getting chunked into several writes, which is fine, possibly just a platform difference, maybe they changed the behaviour of >. I forgot to ask, what shell and version of that shell are you running? Bash? Your shell probably has the biggest say on how > behaves.

The openat is being treated as a modify event it seems. I'll have to maybe take a peak at some Linux kernel code and this code to see if this is what we want or expect, if the answer is yes, maybe an update in documentation is all that's required here.

[meow-watermelon]

Hi @ericcurtin,

The shell is bash and the version is 4.4.23. Thanks.

Hui

[ericcurtin]

But what I think is a good idea, is maybe to start writing tests for each C call.

I'll write one for openat and write sometime later, I'll keep you posted.

[github-actions]

We are clearing up our old issues and your ticket has been open for 2 years with no activity. Remove stale label or comment or this will be closed in 30 days.

[NitroCao]

When calling open(2)/openat(2) with O_TRUNC flag, Linux kernel will trigger a IN_MODIFY event before triggering IN_OPEN event. This is why you got more modify events than the number of write calls.