#1 test test_kevent_vnode_disable_and_enable() failed on CentOS 6.3

[Dmitri Shubin]

$ uname -a
Linux sbn.spb.tbricks.com 2.6.32-279.22.1.el6.x86_64 #1 SMP Wed Feb 6 03:10:46 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/redhat-release
CentOS release 6.3 (Final)
$ make check
./kqtest
Running 1 iterations
1: test_peer_close_detection()
2: test_kqueue()
3: test_kevent()
4: test_ev_receipt()
5: test_kevent_socket_add()
6: test_kevent_socket_del()
7: test_kevent_socket_add_without_ev_add()
8: test_kevent_socket_get()
9: test_kevent_socket_disable_and_enable()
10: test_kevent_socket_oneshot()
11: test_kevent_socket_clear()
12: test_kevent_socket_dispatch()
13: test_kevent_socket_listen_backlog()
14: test_kevent_socket_eof()
15: test_kevent_regular_file()
16: test_kevent_signal_add()
17: test_kevent_signal_del()
18: test_kevent_signal_get()
19: test_kevent_signal_disable()
20: test_kevent_signal_enable()
21: test_kevent_signal_oneshot()
22: test_kevent_signal_modify()
23: test_kevent_signal_dispatch()
24: test_kevent_timer_add()
25: test_kevent_timer_del()
26: test_kevent_timer_get()
27: test_kevent_timer_oneshot()
28: test_kevent_timer_periodic()
29: test_kevent_timer_disable_and_enable()
30: test_kevent_timer_dispatch()
31: test_kevent_vnode_add()
32: test_kevent_vnode_del()
33: test_kevent_vnode_disable_and_enable()
test_kevent_vnode_disable_and_enable(): kevent: Resource temporarily unavailable
** ERROR: Program received signal 6
[0x7fffdddf2640]
[0x7fffdddf24e0]
./kqtest[0x408633]
[0x7fffdddf2550]
[0x3ff]
[0x0]
[0x7fffdddf2640]
/lib64/libc.so.6(vsnprintf+0xa2)[0x3978c6f202]
[0x0]
[0x4000000]
/lib64/libc.so.6[0x3978c32920]
[0x0]
[0x0]
[0x0]
[0x0]
[0x0]
[0x0]
[0x0]
[0x0]
[0xbdddf23f0]
[0x7fffdddf2640]
[0x7fffdddf24e0]
./kqtest[0x408633]
[0x7fffdddf2550]
[0x3ff]
[0x0]
[0x7fffdddf2640]
[0x0]
[0x0]
/lib64/libc.so.6[0x3978c3e98f]
[0x1]
[0x10000]
TEST FAILED
make: * [check] Error 1

[Dmitri Shubin]

Looks like the problem is in order of events reported by inotify()
When touch(1)'ing file on CentOS 6 I got IN_OPEN, IN_CLOSE_WRITE and IN_ATTRIB
On Raspbian (Debian for Raspberry Pi, kernel 3.6.11+ #371) I got IN_OPEN. IN_ATTRIB and then IN_CLOSE_WRITE
And since libkqueue removes kevent on receiving IN_CLOSE_XXX the test fails.

[Eric Radman]

The tests pass for me on CentOS 6.4

$ uname -a
Linux drdenws04 2.6.32-358.6.1.el6.x86_64 #1 SMP Tue Apr 23 19:29:00 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

Proper ordering is supposed to be a promise; from the inotify(7) man page:

The events returned by reading from an inotify file descriptor form
an ordered queue.  Thus, for example, it is guaranteed that when
renaming from one directory to another, events will be produced in
the correct order on the inotify file descriptor.

I assume you're using ext3/4? It shouldn't matter, but I have seen wrong behavior on NFS mountpoints.

[Dmitri Shubin]

Hmm, I'm on CentOS 6.4 now too, but the events have the same order as I described for CentOS 6.3

Could you please check small test attached -- it simply watches 'test-file' in current directory.
When I touch this file from another console I got the following:

sbn@sbn $ gcc inotify-touch.c
sbn@sbn $ ./a.out
wd=1 mask = 32 (IN_OPEN)
wd=1 mask = 8 (IN_CLOSE_WRITE)
wd=1 mask = 4 (IN_ATTRIB)
wd=1 mask = 32 (IN_OPEN)
wd=1 mask = 16 (IN_CLOSE_NOWRITE)

// touching in another console

wd=1 mask = 32 (IN_OPEN)
wd=1 mask = 8 (IN_CLOSE_WRITE)
wd=1 mask = 4 (IN_ATTRIB)
^C
sbn@sbn $ uname -a
Linux sbn.spb.tbricks.com 2.6.32-358.6.1.el6.x86_64 #1 SMP Tue Apr 23 19:29:00 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

[Eric Radman]

Remarkable, the output I receive is different, but we're using the exact same Kernel!

$ gcc inotify-touch.c
$ ./a.out
wd=1 mask = 32 (IN_OPEN)
wd=1 mask = 4 (IN_ATTRIB)
wd=1 mask = 8 (IN_CLOSE_WRITE)

// touch test-file in another console

wd=1 mask = 32 (IN_OPEN)
wd=1 mask = 4 (IN_ATTRIB)
wd=1 mask = 8 (IN_CLOSE_WRITE)

$ uname -a
Linux drdenws04 2.6.32-358.6.1.el6.x86_64 #1 SMP Tue Apr 23 19:29:00 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

[Dmitri Shubin]

Ok, I found it -- the problem is in 'touch' in fact.
I happen to use some old 'touch' version, not /bin/touch
With /bin/touch result is the same as yours.

$ touch --version | head -1
touch (coreutils) 5.2.1
$ /bin/touch --version | head -1
touch (GNU coreutils) 8.4

The difference is in the order of syscalls:

$ strace touch test-file
execve("/home/sbn/bin/Linux-x86_64/bin/touch", ["touch", "test-file"], [/ 55 vars /]) = 0
...
open("test-file", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) = 3
close(3) = 0
utime("test-file", NULL) = 0
exit_group(0) = ?
$ strace /bin/touch test-file
execve("/bin/touch", ["/bin/touch", "test-file"], [/ 55 vars /]) = 0
open("test-file", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) = 3
dup2(3, 0) = 0
close(3) = 0
utimensat(0, NULL, NULL, 0) = 0
close(0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?

So old does: open - close - utime, while the new one -- open - utime - close

[Mark Heily]

Since we support Windows as a platform, it would be good to replace the call to "touch" with a simple pair of open() and close() syscalls.

Also, kqtest should probably set an explicit PATH of /bin:/usr/bin:/usr/local/bin so we don't get any more surprises of what binaries are invoked.

[Eric Radman]

Could every instance of testfile_touch() be replaced with testfile_create()?

[Mark Heily]

It's a nice idea, but I tried replacing testfile_touch() with testfile_create() and it did not work.