Inotify problem [was Re: 2.6.13-rc6-mm1]
From: Reuben Farrelly
Date: Thu Aug 25 2005 - 05:08:24 EST
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@xxxxxxxx> 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
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/