Inotify problem [was Re: 2.6.13-rc6-mm1]

Inotify problem [was Re: 2.6.13-rc6-mm1]

[Reuben Farrelly]

Hi,

On 22/08/2005 9:10 p.m., John McCutchan wrote:
> On Sat, 2005-08-20 at 23:52 -0700, Andrew Morton wrote:
>> Reuben Farrelly <reuben-lkml@reub.net> wrote:
>>> Hi,
>>>
>>> On 19/08/2005 11:37 a.m., Andrew Morton wrote:
>>>> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.13-rc6/2.6.13-rc6-mm1/
>>>>
>>>> - Lots of fixes, updates and cleanups all over the place.
>>>>
>>>> - If you have the right debugging options set, this kernel will generate
>>>>   a storm of sleeping-in-atomic-code warnings at boot, from the scsi code.
>>>>   It is being worked on.
>>>>
>>>>
>>>> Changes since 2.6.13-rc5-mm1:
>>>>
>>>>  linus.patch
>>> Noted this in my log earlier today.
>>>
>>> Is this inotify related?
>>>
>>> Aug 21 08:33:04 tornado kernel: idr_remove called for id=2048 which is not 
>>> allocated.
>>> Aug 21 08:33:04 tornado kernel:  [<c0103a00>] dump_stack+0x17/0x19
>>> Aug 21 08:33:04 tornado kernel:  [<c01c9f9a>] idr_remove_warning+0x1b/0x1d
>>> Aug 21 08:33:04 tornado kernel:  [<c01ca024>] sub_remove+0x88/0xea
>>> Aug 21 08:33:04 tornado kernel:  [<c01ca0a1>] idr_remove+0x1b/0x7f
>>> Aug 21 08:33:04 tornado kernel:  [<c018176a>] remove_watch_no_event+0x7a/0x12e
>>> Aug 21 08:33:04 tornado kernel:  [<c0181f64>] inotify_release+0x8f/0x1af
>>> Aug 21 08:33:04 tornado kernel:  [<c015ca80>] __fput+0xaf/0x199
>>> Aug 21 08:33:04 tornado kernel:  [<c015c9b8>] fput+0x22/0x3b
>>> Aug 21 08:33:04 tornado kernel:  [<c015b2ed>] filp_close+0x41/0x67
>>> Aug 21 08:33:04 tornado kernel:  [<c015b383>] sys_close+0x70/0x92
>>> Aug 21 08:33:04 tornado kernel:  [<c0102a9b>] sysenter_past_esp+0x54/0x75
>>> Aug 21 08:33:04 tornado kernel: idr_remove called for id=3072 which is not 
>>> allocated.
>>> Aug 21 08:33:05 tornado kernel:  [<c0103a00>] dump_stack+0x17/0x19
>>> Aug 21 08:33:05 tornado kernel:  [<c01c9f9a>] idr_remove_warning+0x1b/0x1d
>>> Aug 21 08:33:05 tornado kernel:  [<c01ca024>] sub_remove+0x88/0xea
>>> Aug 21 08:33:05 tornado kernel:  [<c01ca0a1>] idr_remove+0x1b/0x7f
>>> Aug 21 08:33:05 tornado kernel:  [<c018176a>] remove_watch_no_event+0x7a/0x12e
>>> Aug 21 08:33:05 tornado kernel:  [<c0181f64>] inotify_release+0x8f/0x1af
>>> Aug 21 08:33:05 tornado kernel:  [<c015ca80>] __fput+0xaf/0x199
>>> Aug 21 08:33:05 tornado kernel:  [<c015c9b8>] fput+0x22/0x3b
>>> Aug 21 08:33:05 tornado kernel:  [<c015b2ed>] filp_close+0x41/0x67
>>> Aug 21 08:33:05 tornado kernel:  [<c015b383>] sys_close+0x70/0x92
>>> Aug 21 08:33:05 tornado kernel:  [<c0102a9b>] sysenter_past_esp+0x54/0x75
>>>
>>> This would have been triggered by using dovecot IMAP which is configured to 
>>> use inotify on Maildir.
>>> I'm also seeing some userspace errors logged for dovecot:
>>>
>>> "Aug 21 04:17:22 Error: IMAP(reuben): inotify_rm_watch() failed: Invalid argument"
>>>
>>> I'll deal with those with the guy who wrote the inotify code in dovecot.
>>>
>>> I'm not so sure userspace should be able or need to cause the kernel to dump 
>>> stack traces like that though?
>>>
>> Yes, the stack dumps would appear to be due to an inotify bug.
>>
>> The message from dovecot is allegedly due to dovecot passing in a file
>> descriptor which was not obtained from the inotify_init() syscall.  But
>> until we know what caused those stack dumps we cannot definitely say
>> whether dovecot is at fault.
>>
> 
> Inotify has a check on both add and rm watch syscalls:
> 
>     /* verify that this is indeed an inotify instance */
>     if (unlikely(filp->f_op != &inotify_fops)) {
>         ret = -EINVAL;
>         goto out;
>     }
> 
> This is crashing in inotify_release, which is called on close of the
> inotify instance. So this fd must be from an inotify instance right?
> 
> I looked at the dovecot code, it looks fine wrt inotify. Long shot, but
> the close-on-exec flag is set. Could this be tripping anything up?

I have also observed another problem with inotify with dovecot - so I spoke 
with Johannes Berg who wrote the inotify code in dovecot.  He suggested I post 
here to LKML since his opinion is that this to be a kernel bug.

The problem I am observing is this, logged by dovecot after a period of time 
when a client is connected:

dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
Invalid argument
dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
Invalid argument
dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
Invalid argument

Multiply that by about 1000 ;-)

Some debugging shows this:
dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1018 from inotify fd 4
dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1019
dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1020
dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1020
dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1021
dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1021
dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1022
dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1022
dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1023
dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1023
dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1024
dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1024 from inotify fd 4
dovecot: Aug 25 19:31:27 Error: IMAP(gilly): inotify_rm_watch() failed: 
Invalid argument
dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024

Note the incrementing wd value even though we are removing them as we go..

This is using latest CVS of dovecot code and with 2.6.12-rc6-mm(1|2) kernel.

Robert, John, what do you think?   Is this possibly related to the oops seen 
in the log that I reported earlier?  (Which is still showing up 2-3 times per 
day, btw)

Reuben

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1446 bytes --]

Hi,

> I have also observed another problem with inotify with dovecot - so I spoke 
> with Johannes Berg who wrote the inotify code in dovecot.  He suggested I post 
> here to LKML since his opinion is that this to be a kernel bug.

Allow me to jump in at this point. The small tool below triggers this
problem for Reuben (confirmed via private mail) but works fine for me on
2.6.13-rc6.

johannes

--begin test program--
/* Author: Johannes Berg <johannes@sipsolutions.net>
 *
 * This is a small inotify test program that simply
 * repeatedly adds and removes watches.
 */

#include <stdio.h>
#include <linux/inotify.h>
#include <linux/inotify-syscalls.h>

int main()
{
	int fd;
	int wd1, wd2;
	int ret;

	fd = inotify_init();

	if (fd < 0)
		perror("inotify_init");

	printf("inotify_init returned fd %d\n", fd);

	while (1) {
		wd1 = inotify_add_watch(fd, "/tmp", IN_ALL_EVENTS);

		if (wd1 < 0) {
			perror("inotify_add_watch");
			break;
		}
		printf("inotify_add_watch returned wd1 %d\n", wd1);

		wd2 = inotify_add_watch(fd, "/", IN_ALL_EVENTS);

		if (wd2 < 0) {
			perror("inotify_add_watch");
			break;
		}
		printf("inotify_add_watch returned wd2 %d\n", wd2);

		ret = inotify_rm_watch(fd, wd1);
		if (ret < 0) {
			perror("inotify_rm_watch wd1");
			break;
		}
		ret = inotify_rm_watch(fd, wd2);
		if (ret < 0) {
			perror("inotify_rm_watch wd2");
			break;
		}
	}
}


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 22:07 +1200, Reuben Farrelly wrote:
> Hi,
> 
> I have also observed another problem with inotify with dovecot - so I spoke 
> with Johannes Berg who wrote the inotify code in dovecot.  He suggested I post 
> here to LKML since his opinion is that this to be a kernel bug.
> 
> The problem I am observing is this, logged by dovecot after a period of time 
> when a client is connected:
> 
> dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> Invalid argument
> dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> Invalid argument
> dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> Invalid argument
> 
> Multiply that by about 1000 ;-)
> 
> Some debugging shows this:
> dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
> dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1018 from inotify fd 4
> dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1019
> dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1020
> dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
> dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
> dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1020



> dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1021
> dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
> dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
> dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1021
> dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1022
> dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
> dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
> dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1022
> dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1023
> dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
> dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
> dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1023
> dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1024
> dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1024 from inotify fd 4
> dovecot: Aug 25 19:31:27 Error: IMAP(gilly): inotify_rm_watch() failed: 
> Invalid argument
> dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
> dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> 
> Note the incrementing wd value even though we are removing them as we go..
> 

What kernel are you running? The wd's should ALWAYS be incrementing, you
should never get the same wd as you did before. From your log, you are
getting the same wd (after you inotify_rm_watch it). I can reproduce
this bug on 2.6.13-rc7.

idr_get_new_above 

isn't returning something above.

Also, the idr layer seems to be breaking when we pass in 1024. I can
reproduce that on my 2.6.13-rc7 system as well.

> This is using latest CVS of dovecot code and with 2.6.12-rc6-mm(1|2) kernel.
> 
> Robert, John, what do you think?   Is this possibly related to the oops seen 
> in the log that I reported earlier?  (Which is still showing up 2-3 times per 
> day, btw)

There is definitely something broken here.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 14:18 +0200, Johannes Berg wrote:
> Hi,
> 
> > I have also observed another problem with inotify with dovecot - so I spoke 
> > with Johannes Berg who wrote the inotify code in dovecot.  He suggested I post 
> > here to LKML since his opinion is that this to be a kernel bug.
> 
> Allow me to jump in at this point. The small tool below triggers this
> problem for Reuben (confirmed via private mail) but works fine for me on
> 2.6.13-rc6.

On 2.6.13-rc7 the test program fails. It always fails when a wd == 1024.
If I skip inotify_rm_watch when wd == 1024, it will fail at wd == 2048.
It seems the idr layer has an aversion to multiples of 1024.

When I run your test program I get this a lot:

inotify_add_watch returned wd1 5
inotify_add_watch returned wd2 6
inotify_add_watch returned wd1 6
inotify_add_watch returned wd2 7

The pattern of 

add_watch wd1 = X
add_watch wd2 = X+1
rm_watch X
rm_watch X+1
add_watch wd1 = X+1
add_watch wd2 = X+2

Should never happen. We tell the idr layer to always give us something
bigger than the last wd we received.

Also, idr_get_new_above doesn't work all the time. Under 2.6.13-rc7, I
added this to inotify.c:359:

if (ret <= dev->last_wd) {
    printk(KERN_INFO "idr_get_new_above returned <= dev->last_wd\n");
}

I get that message a lot. I know I have said this before (and was wrong)
but I think the idr layer is busted.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Robert Love]

On Thu, 2005-08-25 at 09:40 -0400, John McCutchan wrote:

> I get that message a lot. I know I have said this before (and was wrong)
> but I think the idr layer is busted.

This time I think I agree with you.  ;-)

Let's just pass zero for the "above" parameter in idr_get_new_above(),
which is I believe the behavior of the other interface, and see if the
1024-multiple problem goes away.  We definitely did not have that
before.

If it does, and we don't have another solution, let's run with that for
2.6.13.  I don't want this bug released.

	Robert Love

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 692 bytes --]

On Thu, 2005-08-25 at 09:40 -0400, John McCutchan wrote:

> On 2.6.13-rc7 the test program fails. It always fails when a wd == 1024.
> If I skip inotify_rm_watch when wd == 1024, it will fail at wd == 2048.
> It seems the idr layer has an aversion to multiples of 1024.
> 
> When I run your test program I get this a lot:

I forgot to mention this -- but I just get (on -rc6):

inotify_add_watch returned wd1 0
inotify_add_watch returned wd2 1
inotify_add_watch returned wd1 0
inotify_add_watch returned wd2 1
inotify_add_watch returned wd1 0
inotify_add_watch returned wd2 1

etc.

IOW, they are directly reused, not even with the +1 offset you were
seeing.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 15:50 +0200, Johannes Berg wrote:
> On Thu, 2005-08-25 at 09:40 -0400, John McCutchan wrote:
> 
> > On 2.6.13-rc7 the test program fails. It always fails when a wd == 1024.
> > If I skip inotify_rm_watch when wd == 1024, it will fail at wd == 2048.
> > It seems the idr layer has an aversion to multiples of 1024.
> > 
> > When I run your test program I get this a lot:
> 
> I forgot to mention this -- but I just get (on -rc6):
> 
> inotify_add_watch returned wd1 0
> inotify_add_watch returned wd2 1
> inotify_add_watch returned wd1 0
> inotify_add_watch returned wd2 1
> inotify_add_watch returned wd1 0
> inotify_add_watch returned wd2 1

Yeah, pre -rc7 we were always passing in 0 to idr_get_new_above. With
rc7 we pass in the last wd returned.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 552 bytes --]

On Thu, 2005-08-25 at 09:47 -0400, Robert Love wrote:

> Let's just pass zero for the "above" parameter in idr_get_new_above(),
> which is I believe the behavior of the other interface, and see if the
> 1024-multiple problem goes away.  We definitely did not have that
> before.

Will we then need to test if it fails for more than 1024 watches?

If I adjust the program to

1) create /tmp/test/%d
2) watch /tmp/test/%d
3) repeat

it fails on 2.6.13-rc6 as soon as the device is full and doesn't hold
any more directories.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 16:03 +0200, Johannes Berg wrote:
> On Thu, 2005-08-25 at 09:47 -0400, Robert Love wrote:
> 
> > Let's just pass zero for the "above" parameter in idr_get_new_above(),
> > which is I believe the behavior of the other interface, and see if the
> > 1024-multiple problem goes away.  We definitely did not have that
> > before.
> 
> Will we then need to test if it fails for more than 1024 watches?
> 
> If I adjust the program to
> 
> 1) create /tmp/test/%d
> 2) watch /tmp/test/%d
> 3) repeat
> 
> it fails on 2.6.13-rc6 as soon as the device is full and doesn't hold
> any more directories.

Could you send me the new test program?

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1282 bytes --]

On Thu, 2005-08-25 at 10:06 -0400, John McCutchan wrote:
> > it fails on 2.6.13-rc6 as soon as the device is full and doesn't hold
> > any more directories.

Obviously this wasn't true, I was hitting the 8192 watches limit and
misinterpreted the error message. I just tested up to 100000 watches
with this program.

> Could you send me the new test program?

Below.

johannes

/* Author: Johannes Berg <johannes@sipsolutions.net>
 *
 * This is another small inotify test program that simply
 * repeatedly adds watches.
 */

#include <stdio.h>
#include <linux/inotify.h>
#include <linux/inotify-syscalls.h>

int main()
{
	int fd;
	int wd1, wd2;
	int ret, i = 0;
	char buf[1024];

	fd = inotify_init();

	if (fd < 0)
		perror("inotify_init");

	printf("inotify_init returned fd %d\n", fd);
	
	mkdir("/tmp/inotify-test-dir-rm-rf-this", 0777);

	while (1) {
		i++;
		snprintf(buf,sizeof(buf),"/tmp/inotify-test-dir-rm-rf-this/%d",i>>10);
		mkdir(buf,0777);
		snprintf(buf,sizeof(buf),"/tmp/inotify-test-dir-rm-rf-this/%d/%d",i>>10,i);
		mkdir(buf, 0777);
		wd1 = inotify_add_watch(fd, buf, IN_ALL_EVENTS);

		if (wd1 < 0) {
			perror("inotify_add_watch");
			break;
		}
		printf("inotify_add_watch returned wd1 %d\n", wd1);
	}
}


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 09:47 -0400, Robert Love wrote:
> On Thu, 2005-08-25 at 09:40 -0400, John McCutchan wrote:
> 
> > I get that message a lot. I know I have said this before (and was wrong)
> > but I think the idr layer is busted.
> 
> This time I think I agree with you.  ;-)
> 
> Let's just pass zero for the "above" parameter in idr_get_new_above(),
> which is I believe the behavior of the other interface, and see if the
> 1024-multiple problem goes away.  We definitely did not have that
> before.
> 

I will test this.

> If it does, and we don't have another solution, let's run with that for
> 2.6.13.  I don't want this bug released.

I really don't want 2.6.13 to go out with this bug or the compromise. If
we use 0, we will have a lot of wd re-use. Which will cause "strange"
problems in inotify using applications that cleanup upon receipt of an
IN_IGNORE event.

The problem will manifest it self when a program does this:

inotify_add_watch "/x" returns 1
inotify_rm_watch 1
[IN_IGNORE event is queued with wd == 1]
inotify_add_watch "/y" returns 1
application reads events
cleans up data structures associated with wd == 1.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 16:13 +0200, Johannes Berg wrote:
> On Thu, 2005-08-25 at 10:06 -0400, John McCutchan wrote:
> > > it fails on 2.6.13-rc6 as soon as the device is full and doesn't hold
> > > any more directories.
> 
> Obviously this wasn't true, I was hitting the 8192 watches limit and
> misinterpreted the error message. I just tested up to 100000 watches
> with this program.

Thanks. The program runs fine, it climbs up until 8192. This confirmed a
hunch I had. The problem only manifests itself when the lower idr
numbers aren't actually being used. The thread
http://www.redhat.com/archives/dm-devel/2004-July/msg00003.html seems
somewhat related to this problem, but it suggests that this was fixed in
2.6.7.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 838 bytes --]

On Thu, 2005-08-25 at 10:13 -0400, John McCutchan wrote:

> I really don't want 2.6.13 to go out with this bug or the compromise. If
> we use 0, we will have a lot of wd re-use. Which will cause "strange"
> problems in inotify using applications that cleanup upon receipt of an
> IN_IGNORE event.

What happens when, given bug-free code that doesn't reuse, you hit the
8192 limit with wd, even if they're not all open at the same time? Does
it still add them, or will inotify give an error? And does the idr layer
handle something like that gracefully without using lots of memory?

The background is that the process using this is potentially quite
long-running and keeps opening/closing wds, so 8192 doesn't sound like a
high barrier, after all Reuben observed hitting the 1024 limit after 15
minutes or so.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 16:41 +0200, Johannes Berg wrote:
> On Thu, 2005-08-25 at 10:13 -0400, John McCutchan wrote:
> 
> > I really don't want 2.6.13 to go out with this bug or the compromise. If
> > we use 0, we will have a lot of wd re-use. Which will cause "strange"
> > problems in inotify using applications that cleanup upon receipt of an
> > IN_IGNORE event.
> 
> What happens when, given bug-free code that doesn't reuse, you hit the
> 8192 limit with wd, even if they're not all open at the same time? Does
> it still add them, or will inotify give an error? And does the idr layer
> handle something like that gracefully without using lots of memory?
> 

The 8192 limit is the total watches in use at one time. If over time,
you use more than 8192 watches but not all at one time you will just
keep getting higher and higher wd's. I'm not 100% sure if idr handles it
gracefully. 

> The background is that the process using this is potentially quite
> long-running and keeps opening/closing wds, so 8192 doesn't sound like a
> high barrier, after all Reuben observed hitting the 1024 limit after 15
> minutes or so.

There isn't a 1024 limit, that is a bug in the idr code. He got to that
number by having used 1024 wd's throughout the life of the program.'


FYI, if we pass 0 to idr_get_new_above, both your test programs work
fine. But the first one re-uses wd's (back and forth between 0 & 1).

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Robert Love]

On Thu, 2005-08-25 at 09:33 -0400, John McCutchan wrote:
> On Thu, 2005-08-25 at 22:07 +1200, Reuben Farrelly wrote:
> > Hi,
> > 
> > I have also observed another problem with inotify with dovecot - so I spoke 
> > with Johannes Berg who wrote the inotify code in dovecot.  He suggested I post 
> > here to LKML since his opinion is that this to be a kernel bug.
> > 
> > The problem I am observing is this, logged by dovecot after a period of time 
> > when a client is connected:
> > 
> > dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> > Invalid argument
> > dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> > Invalid argument
> > dovecot: Aug 22 14:31:23 Error: IMAP(gilly): inotify_rm_watch() failed: 
> > Invalid argument
> > 
> > Multiply that by about 1000 ;-)
> > 
> > Some debugging shows this:
> > dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
> > dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): removing wd 1018 from inotify fd 4
> > dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1019
> > dovecot: Aug 25 19:31:22 Warning: IMAP(gilly): inotify_add_watch returned 1020
> > dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
> > dovecot: Aug 25 19:31:23 Warning: IMAP(gilly): removing wd 1019 from inotify fd 4
> > dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1020
> 
> 
> 
> > dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): inotify_add_watch returned 1021
> > dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
> > dovecot: Aug 25 19:31:24 Warning: IMAP(gilly): removing wd 1020 from inotify fd 4
> > dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1021
> > dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): inotify_add_watch returned 1022
> > dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
> > dovecot: Aug 25 19:31:25 Warning: IMAP(gilly): removing wd 1021 from inotify fd 4
> > dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1022
> > dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): inotify_add_watch returned 1023
> > dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
> > dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
> > dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1023
> > dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1024
> > dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1024 from inotify fd 4
> > dovecot: Aug 25 19:31:27 Error: IMAP(gilly): inotify_rm_watch() failed: 
> > Invalid argument
> > dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
> > dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> > dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> > 
> > Note the incrementing wd value even though we are removing them as we go..
> > 
> 
> What kernel are you running? The wd's should ALWAYS be incrementing, you
> should never get the same wd as you did before. From your log, you are
> getting the same wd (after you inotify_rm_watch it). I can reproduce
> this bug on 2.6.13-rc7.
> 
> idr_get_new_above 
> 
> isn't returning something above.
> 
> Also, the idr layer seems to be breaking when we pass in 1024. I can
> reproduce that on my 2.6.13-rc7 system as well.
> 
> > This is using latest CVS of dovecot code and with 2.6.12-rc6-mm(1|2) kernel.
> > 
> > Robert, John, what do you think?   Is this possibly related to the oops seen 
> > in the log that I reported earlier?  (Which is still showing up 2-3 times per 
> > day, btw)
> 
> There is definitely something broken here.

Jim, George-

We are seeing a problem in the idr layer.  If we do idr_find(1024) when,
say, a low valued idr, like, zero, is unallocated, NULL is returned.

This readily manifests itself in inotify, where we recently switched to
using idr_get_new_above() with our last allocated token.

	Robert Love

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[George Anzinger]

Robert Love wrote:
> On Thu, 2005-08-25 at 09:33 -0400, John McCutchan wrote:
> 
>>On Thu, 2005-08-25 at 22:07 +1200, Reuben Farrelly wrote:
>>
~
>>>dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
>>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1023
>>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1024
>>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1024 from inotify fd 4
>>>dovecot: Aug 25 19:31:27 Error: IMAP(gilly): inotify_rm_watch() failed: 
>>>Invalid argument
>>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
>>>dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
>>>dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
>>>
>>>Note the incrementing wd value even though we are removing them as we go..
>>>
>>
>>What kernel are you running? The wd's should ALWAYS be incrementing, you
>>should never get the same wd as you did before. From your log, you are
>>getting the same wd (after you inotify_rm_watch it). I can reproduce
>>this bug on 2.6.13-rc7.
>>
>>idr_get_new_above 
>>
>>isn't returning something above.
>>
>>Also, the idr layer seems to be breaking when we pass in 1024. I can
>>reproduce that on my 2.6.13-rc7 system as well.
>>
>>
>>>This is using latest CVS of dovecot code and with 2.6.12-rc6-mm(1|2) kernel.
>>>
>>>Robert, John, what do you think?   Is this possibly related to the oops seen 
>>>in the log that I reported earlier?  (Which is still showing up 2-3 times per 
>>>day, btw)
>>
>>There is definitely something broken here.
> 
> 
> Jim, George-
> 
> We are seeing a problem in the idr layer.  If we do idr_find(1024) when,
> say, a low valued idr, like, zero, is unallocated, NULL is returned.

I think the best thing is to take idr into user space and emulate the 
problem usage.  To this end, from the log it appears that you _might_ be 
moving between 0, 1 and 2 entries increasing the number each time.  It 
also appears that the failure happens here:
add 1023
add 1024
find 1024  or is it the remove that fails?  It also looks like 1024 got 
allocated twice.  Am I reading the log correctly?

So, is it correct to assume that the tree is empty save these two at 
this time?  I am just trying to figure out what the test program needs 
to do.



-- 
George Anzinger   george@mvista.com
HRT (High-res-timers):  http://sourceforge.net/projects/high-res-timers/

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1021 bytes --]

On Thu, 2005-08-25 at 11:54 -0700, George Anzinger wrote:

> I think the best thing is to take idr into user space and emulate the 
> problem usage.  

Good plan, I guess. Do you think that's easy?

> To this end, from the log it appears that you _might_ be 
> moving between 0, 1 and 2 entries increasing the number each time.  It 
> also appears that the failure happens here:
> add 1023
> add 1024
> find 1024  or is it the remove that fails?  It also looks like 1024 got 
> allocated twice.  Am I reading the log correctly?

Remove 1024 fails, but add(please make it >1024) seems to return 1024,
and find(1024) also seems to fail. Well, remove() probably has to
find(), but I'm not really sure what inotify does (maybe find first, to
see if it's valid).

> So, is it correct to assume that the tree is empty save these two at 
> this time?  I am just trying to figure out what the test program needs 
> to do.

Yes, but all the smaller ones have been in it at some point in time.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 11:54 -0700, George Anzinger wrote:
> Robert Love wrote:
> > On Thu, 2005-08-25 at 09:33 -0400, John McCutchan wrote:
> > 
> >>On Thu, 2005-08-25 at 22:07 +1200, Reuben Farrelly wrote:
> >>
> ~
> >>>dovecot: Aug 25 19:31:26 Warning: IMAP(gilly): removing wd 1022 from inotify fd 4
> >>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1023
> >>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): inotify_add_watch returned 1024
> >>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1024 from inotify fd 4
> >>>dovecot: Aug 25 19:31:27 Error: IMAP(gilly): inotify_rm_watch() failed: 
> >>>Invalid argument
> >>>dovecot: Aug 25 19:31:27 Warning: IMAP(gilly): removing wd 1023 from inotify fd 4
> >>>dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> >>>dovecot: Aug 25 19:31:28 Warning: IMAP(gilly): inotify_add_watch returned 1024
> >>>
> >>>Note the incrementing wd value even though we are removing them as we go..
> >>>
> >>
> >>What kernel are you running? The wd's should ALWAYS be incrementing, you
> >>should never get the same wd as you did before. From your log, you are
> >>getting the same wd (after you inotify_rm_watch it). I can reproduce
> >>this bug on 2.6.13-rc7.
> >>
> >>idr_get_new_above 
> >>
> >>isn't returning something above.
> >>
> >>Also, the idr layer seems to be breaking when we pass in 1024. I can
> >>reproduce that on my 2.6.13-rc7 system as well.
> >>
> >>
> >>>This is using latest CVS of dovecot code and with 2.6.12-rc6-mm(1|2) kernel.
> >>>
> >>>Robert, John, what do you think?   Is this possibly related to the oops seen 
> >>>in the log that I reported earlier?  (Which is still showing up 2-3 times per 
> >>>day, btw)
> >>
> >>There is definitely something broken here.
> > 
> > 
> > Jim, George-
> > 
> > We are seeing a problem in the idr layer.  If we do idr_find(1024) when,
> > say, a low valued idr, like, zero, is unallocated, NULL is returned.
> 
> I think the best thing is to take idr into user space and emulate the 
> problem usage.  To this end, from the log it appears that you _might_ be 
> moving between 0, 1 and 2 entries increasing the number each time.  It 
> also appears that the failure happens here:
> add 1023
> add 1024
> find 1024  or is it the remove that fails?  It also looks like 1024 got 
> allocated twice.  Am I reading the log correctly?

You are reading the log correctly. There are two bugs. One is that if we
pass X to idr_get_new_above, it can return X again (doesn't ever seem to
return < X). The other problem is that the find fails on 1024 (and 2048
if we skip 1024).

> 
> So, is it correct to assume that the tree is empty save these two at 
> this time?  I am just trying to figure out what the test program needs 
> to do.

Yes that is the exact scenario. Only 2 id's are used at any given time,
and once we hit 1024 things break. This doesn't happen when the tree is
not empty.

Thanks for looking at this!
-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Thu, 2005-08-25 at 21:03 +0200, Johannes Berg wrote:
> On Thu, 2005-08-25 at 11:54 -0700, George Anzinger wrote:
> 
> > I think the best thing is to take idr into user space and emulate the 
> > problem usage.  
> 
> Good plan, I guess. Do you think that's easy?
> 
> > To this end, from the log it appears that you _might_ be 
> > moving between 0, 1 and 2 entries increasing the number each time.  It 
> > also appears that the failure happens here:
> > add 1023
> > add 1024
> > find 1024  or is it the remove that fails?  It also looks like 1024 got 
> > allocated twice.  Am I reading the log correctly?
> 
> Remove 1024 fails, but add(please make it >1024) seems to return 1024,
> and find(1024) also seems to fail. Well, remove() probably has to
> find(), but I'm not really sure what inotify does (maybe find first, to
> see if it's valid).

Just to clarify, the remove() he is talking about isn't idr_remove, it
is inotify's remove. idr_find() is failing at 1024 which causes
inotify's remove to fail.

-- 
John McCutchan <ttb@tentacle.dhs.org>

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[George Anzinger]

John McCutchan wrote:
> On Thu, 2005-08-25 at 11:54 -0700, George Anzinger wrote:
> 
>>Robert Love wrote:
>>
>>>On Thu, 2005-08-25 at 09:33 -0400, John McCutchan wrote:
>>>
>>>
>>>>On Thu, 2005-08-25 at 22:07 +1200, Reuben Farrelly wrote:
~
>>I think the best thing is to take idr into user space and emulate the 
>>problem usage.  To this end, from the log it appears that you _might_ be 
>>moving between 0, 1 and 2 entries increasing the number each time.  It 
>>also appears that the failure happens here:
>>add 1023
>>add 1024
>>find 1024  or is it the remove that fails?  It also looks like 1024 got 
>>allocated twice.  Am I reading the log correctly?
> 
> 
> You are reading the log correctly. There are two bugs. One is that if we
> pass X to idr_get_new_above, it can return X again (doesn't ever seem to
> return < X). The other problem is that the find fails on 1024 (and 2048
> if we skip 1024).

That IS strange.  1024 is on a "level" boundry, but then next level is 
2**15, not 2**11.  I will take a look.

> 
> 
>>So, is it correct to assume that the tree is empty save these two at 
>>this time?  I am just trying to figure out what the test program needs 
>>to do.
> 
> 
> Yes that is the exact scenario. Only 2 id's are used at any given time,
> and once we hit 1024 things break. This doesn't happen when the tree is
> not empty.
> 
> Thanks for looking at this!

-- 
George Anzinger   george@mvista.com
HRT (High-res-timers):  http://sourceforge.net/projects/high-res-timers/

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 397 bytes --]

On Thu, 2005-08-25 at 16:10 -0700, George Anzinger wrote:

> That IS strange.  1024 is on a "level" boundry, but then next level is 
> 2**15, not 2**11.  I will take a look.

Remember that the level is never filled, so maybe the smallest level
just gets an offset or something? Well, you're the expert I suppose, so
apologies if this didn't make sense. Just crossed my mind :)

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Jim Houston]

Hi Everyone,

I'm answering this from my home email. I have not heard from my
co-workers in Florida yet, and I imagine that they are busy cleaning up
after hurricane Katrina and waiting for the power to come back on.

It looks like we have an "off by one" problem with idr_get_new_above()
which may be part of the inotify problem.  I'm not sure if the problem
is the behavior or the name & comments.  The start_id parameter is the
starting point for the idr allocation search, and if it is available, it
will be allocated.  If you pass in the last id allocated as the start_id
and it has already been freed (by an idr_remove call), it will be
allocated again.  The obvious fix would be to increment start_id
in idr_get_new_above().

I would be glad to spend some time looking at the inotify problem
assuming that fixing the off-by-one problem above doesn't solve
it.  I have not used inotify and would need pointers to the user
space header files and library.

Jim

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[John McCutchan]

On Fri, 2005-08-26 at 13:03 -0400, Jim Houston wrote:
> Hi Everyone,
> 
> I'm answering this from my home email. I have not heard from my
> co-workers in Florida yet, and I imagine that they are busy cleaning up
> after hurricane Katrina and waiting for the power to come back on.
> 
> It looks like we have an "off by one" problem with idr_get_new_above()
> which may be part of the inotify problem.  I'm not sure if the problem
> is the behavior or the name & comments.  The start_id parameter is the
> starting point for the idr allocation search, and if it is available, it
> will be allocated.  If you pass in the last id allocated as the start_id
> and it has already been freed (by an idr_remove call), it will be
> allocated again.  The obvious fix would be to increment start_id
> in idr_get_new_above().

Thanks for your suggestion, it has fixed the inotify problem. But where
to put the fix is turning into a bit of a mess. Some callers like
drivers/md/dm.c:682 call idr_get_new_above as if it will return >=
starting_id. The comment says that it will return > starting_id, and the
function name leads people to believe the same thing. In the patch below
I change inotify do add one to the value was pass into idr. I also
change the comment to more accurately reflect what the function does.
The function name doesn't fit, but it never did.

Signed-off-by: John McCutchan <ttb@tentacle.dhs.org>

Index: linux/fs/inotify.c
===================================================================
--- linux.orig/fs/inotify.c	2005-08-26 13:38:29.000000000 -0400
+++ linux/fs/inotify.c	2005-08-26 13:38:55.000000000 -0400
@@ -353,7 +353,7 @@
 	do {
 		if (unlikely(!idr_pre_get(&dev->idr, GFP_KERNEL)))
 			return -ENOSPC;
-		ret = idr_get_new_above(&dev->idr, watch, dev->last_wd, &watch->wd);
+		ret = idr_get_new_above(&dev->idr, watch, dev->last_wd+1, &watch->wd);
 	} while (ret == -EAGAIN);
 
 	return ret;
Index: linux/lib/idr.c
===================================================================
--- linux.orig/lib/idr.c	2005-08-26 13:38:22.000000000 -0400
+++ linux/lib/idr.c	2005-08-26 13:39:08.000000000 -0400
@@ -207,7 +207,7 @@
 }
 
 /**
- * idr_get_new_above - allocate new idr entry above a start id
+ * idr_get_new_above - allocate new idr entry above or equal to a start id
  * @idp: idr handle
  * @ptr: pointer you want associated with the ide
  * @start_id: id to start search at

Re: Inotify problem [was Re: 2.6.13-rc6-mm1]

[Robert Love]

On Fri, 2005-08-26 at 13:52 -0400, John McCutchan wrote:

> Thanks for your suggestion, it has fixed the inotify problem. But where
> to put the fix is turning into a bit of a mess. Some callers like
> drivers/md/dm.c:682 call idr_get_new_above as if it will return >=
> starting_id. The comment says that it will return > starting_id, and the
> function name leads people to believe the same thing. In the patch below
> I change inotify do add one to the value was pass into idr. I also
> change the comment to more accurately reflect what the function does.
> The function name doesn't fit, but it never did.
> 
> Signed-off-by: John McCutchan <ttb@tentacle.dhs.org>

Signed-off-by: Robert Love <rml@novell.com>

Keeping the current behavior is probably the best way to go.

	Robert Love

> Index: linux/fs/inotify.c
> ===================================================================
> --- linux.orig/fs/inotify.c	2005-08-26 13:38:29.000000000 -0400
> +++ linux/fs/inotify.c	2005-08-26 13:38:55.000000000 -0400
> @@ -353,7 +353,7 @@
>  	do {
>  		if (unlikely(!idr_pre_get(&dev->idr, GFP_KERNEL)))
>  			return -ENOSPC;
> -		ret = idr_get_new_above(&dev->idr, watch, dev->last_wd, &watch->wd);
> +		ret = idr_get_new_above(&dev->idr, watch, dev->last_wd+1, &watch->wd);
>  	} while (ret == -EAGAIN);
>  
>  	return ret;
> Index: linux/lib/idr.c
> ===================================================================
> --- linux.orig/lib/idr.c	2005-08-26 13:38:22.000000000 -0400
> +++ linux/lib/idr.c	2005-08-26 13:39:08.000000000 -0400
> @@ -207,7 +207,7 @@
>  }
>  
>  /**
> - * idr_get_new_above - allocate new idr entry above a start id
> + * idr_get_new_above - allocate new idr entry above or equal to a start id
>   * @idp: idr handle
>   * @ptr: pointer you want associated with the ide
>   * @start_id: id to start search at
>