Created attachment 310761 [details]
ujf Kernel module

Created attachment 310763 [details]
Full CPU soft lockup and Kernel panic log

What exactly are you trying to accomplish with this kernel module? I'm not sure
that jumping jiffies64 forward like that is a legitimate thing to do.

If the NMI watchdog kicked in then it's because the timer interrupt doesn't look
like it's being serviced (i.e. jiffies hasn't advanced in several seconds).

In fact, this message is in your logs:

ujf jf 119c42aef jf_64 11eea86ef\n<3>BUG: soft lockup - CPU#1 stuck for 86400s!
[klogd:2464]

...I think this method of jumping jiffies64 forward is tricking the nmi watchdog
into firing:

1) jiffies64 was recorded in the nmi handler
2) you jumped it forward by a day
3) the nmi fired again, and when we compared the new jiffies64 to the old one,
it looked like it hadn't been serviced in a long time

This really looks like NOTABUG, and really doesn't seem to be anything to do
with NFS. I suggest we close it as such, though I'm willing to listen if you
think we shouldn't...

Originally, This is a regression RHTS test of NFS attribute timeout handling and
wrapping u32 jiffies for RHEL 4.6.z Kernel,

/kernel/errata/4.6.z/371551

I have accidentally tried it on RHEL 5.2.z, but it gave me a Kernel panic
instead, so I reported it here. You could find the detailed problem description at,

https://bugzilla.redhat.com/show_bug.cgi?id=247905
http://marc.info/?l=linux-nfs&m=118533288523256&w=2

Propose for inclusion of 5.3. Otherwise, we'll have a regression path from 4.7
to 5.3.

I tried this kernel module out on a kernel-debug kernel from my people page:

     http://people.redhat.com/jlayton/

I was able to work on the console of my FV xen guest, but the network no longer
worked after plugging it in with adjdays=25. I had no NFS mounts and was not
serving NFS at all.

Jumping jiffies forward like this seems very likely to have unpredictable
effects. It certainly is making the softlockup messages pop here.

I suspect that what happened here is that the code running on CPU1 didn't deal
well with this sudden jump in jiffies and hung. This caused it to miss bumping
the perf counters on the CPU for 30s and the NMI watchdog crashed the box:

Here's the stack trace for CPU1 at the time:

NMI Watchdog detected LOCKUP on CPU 1
CPU 1 
Modules linked in: ujf(U) nfs fscache nfsd exportfs lockd nfs_acl auth_rpcgss
autofs4 hidp rfcomm l2cap bluetooth sunrpc ipv6 xfrm_nalgo crypto_api
dm_multipath video sbs backlight i2c_ec button battery asus_acpi acpi_memhotplug
ac parport_pc lp parport sg ide_cd i6300esb floppy i2c_i801 shpchp cdrom e1000
serio_raw i2c_core pcspkr dm_snapshot dm_zero dm_mirror dm_mod ata_piix libata
sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 3236, comm: insmod Tainted: G      2.6.18-92.el5 #1
RIP: 0010:[<ffffffff800621d1>]  [<ffffffff800621d1>] __write_lock_failed+0x9/0x20
RSP: 0018:ffff81003055bd58  EFLAGS: 00000087
RAX: ffff81003e3943c0 RBX: ffff810037ffdc80 RCX: 000000000000006d
RDX: 0000000000000000 RSI: 000000000000006d RDI: ffffffff803b5e80
RBP: ffff81003c4a3040 R08: 0000000000000001 R09: ffff810037ffdc80
R10: ffff81003eb77cc0 R11: ffff81003eb77cc0 R12: ffff81003c4a3040
R13: ffff81003055be78 R14: ffff81003055bef8 R15: ffff81003055bf58
FS:  0000000000000000(0000) GS:ffff810037c817c0(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00002aaaab4ba000 CR3: 0000000000201000 CR4: 00000000000006e0
Process insmod (pid: 3236, threadinfo ffff81003055a000, task ffff81003c4a3040)
Stack:  ffffffff80064b0b ffffffff80015456 0000000000000001 0000000000000000
 000000013c4a35f8 0000000000000009 0000000000000001 00007fffad779bd1
 ffff81003055be78 ffffffff80048a1c 0000000000000009 ffff81003055bf58
Call Trace:
 [<ffffffff80064b0b>] _write_lock_irq+0xf/0x10
 [<ffffffff80015456>] do_exit+0x52b/0x8d0
 [<ffffffff80048a1c>] cpuset_exit+0x0/0x6c
 [<ffffffff8002b05b>] get_signal_to_deliver+0x42c/0x45a
 [<ffffffff8005aa43>] do_notify_resume+0x9c/0x7a9
 [<ffffffff80142f55>] __next_cpu+0x19/0x28
 [<ffffffff80062abd>] __sched_text_start+0x6ad/0xaeb
 [<ffffffff8003d671>] lock_timer_base+0x1b/0x3c
 [<ffffffff8004a946>] try_to_del_timer_sync+0x51/0x5a
 [<ffffffff800b4326>] audit_syscall_exit+0x31b/0x336
 [<ffffffff8005d32e>] int_signal+0x12/0x17

...that doesn't look NFS related to me. It looks like signal handling code. Did
you hit ^c or something here?

Now, it may be that your kernel module is doing something legitimate and that is
exposing bugs in jiffies handling in other pieces of code. I'm not certain.

If you want to pursue this, there are a couple of things I'd suggest:

1) disable the nmi_watchdog by booting the kernel with nmi_watchdog=0. In this
case, that would have prevented the crash, but you would still have probably had
a stuck CPU#1.

2) work with a kernel-debug and track down a way to make it so that you can plug
this in and not get any warnings or errors, and still have everything work. That
may take a while, but if you think that jumping jiffies64 like this is OK, then
post this module upstream and start reporting bugs.

For now, I'm going to devel_nak this bug since I'm not convinced that this is a
bug in our code. It's certainly not a NFS problem.

Setting to NEEDINFO reporter.

OK. Thanks for analyzing. Let us forget about 64bit and that Kernel module
first. The most important thing is that there looks like a bug fixed in RHEL4,
but not here.

247905: ls -l shows out-dated timestamp and other attributes

On a i686 machine, I ran the following test case,

echo "Prepare NFS mount."
mkdir /root/nfs /mnt/testarea/nfs
echo "/root/nfs *(rw,no_root_squash,sync)" >/etc/exports
service nfs restart
mount localhost:/root/nfs /mnt/testarea/nfs

echo "Create files and save first timestamps of files."
cd /mnt/testarea/nfs
touch A B BH G
mkdir C D
ln -s B E
ln BH EH
ln G GH
ln -s D F
ls -l >/tmp/1 # Without this line, the bug does not show.

echo "Wait for a minute."
sleep 60

echo "Touch all files."
cd /root/nfs
touch A C E EH F G

ls -l /root/nfs /mnt/testarea/nfs

echo "Clean up."
umount /mnt/testarea/nfs
rm -rf /mnt/testarea/nfs
rm -rf /root/nfs

On RHEL5 Kernel,

/mnt/testarea/nfs:
total 48
-rw-r--r-- 1 root root    0 Jul 17 02:59 A
-rw-r--r-- 1 root root    0 Jul 17 02:59 B
-rw-r--r-- 2 root root    0 Jul 17 02:59 BH
drwxr-xr-x 2 root root 4096 Jul 17 02:59 C
drwxr-xr-x 2 root root 4096 Jul 17 02:59 D
lrwxrwxrwx 1 root root    1 Jul 17 02:59 E -> B
-rw-r--r-- 2 root root    0 Jul 17 02:59 EH
lrwxrwxrwx 1 root root    1 Jul 17 02:59 F -> D
-rw-r--r-- 2 root root    0 Jul 17 02:59 G
-rw-r--r-- 2 root root    0 Jul 17 02:59 GH

/root/nfs:
total 48
-rw-r--r-- 1 root root    0 Jul 17 03:01 A
-rw-r--r-- 1 root root    0 Jul 17 03:01 B
-rw-r--r-- 2 root root    0 Jul 17 03:01 BH
drwxr-xr-x 2 root root 4096 Jul 17 03:01 C
drwxr-xr-x 2 root root 4096 Jul 17 03:01 D
lrwxrwxrwx 1 root root    1 Jul 17 02:59 E -> B
-rw-r--r-- 2 root root    0 Jul 17 03:01 EH
lrwxrwxrwx 1 root root    1 Jul 17 02:59 F -> D
-rw-r--r-- 2 root root    0 Jul 17 03:01 G
-rw-r--r-- 2 root root    0 Jul 17 03:01 GH

If without "ls -l >/tmp/1" line, the timestamp looks like has been updated,

/mnt/testarea/nfs:
total 48
-rw-r--r-- 1 root root    0 Jul 17 03:09 A
-rw-r--r-- 1 root root    0 Jul 17 03:09 B
-rw-r--r-- 2 root root    0 Jul 17 03:09 BH
drwxr-xr-x 2 root root 4096 Jul 17 03:09 C
drwxr-xr-x 2 root root 4096 Jul 17 03:09 D
lrwxrwxrwx 1 root root    1 Jul 17 03:07 E -> B
-rw-r--r-- 2 root root    0 Jul 17 03:09 EH
lrwxrwxrwx 1 root root    1 Jul 17 03:07 F -> D
-rw-r--r-- 2 root root    0 Jul 17 03:09 G
-rw-r--r-- 2 root root    0 Jul 17 03:09 GH

/root/nfs:
total 48
-rw-r--r-- 1 root root    0 Jul 17 03:09 A
-rw-r--r-- 1 root root    0 Jul 17 03:09 B
-rw-r--r-- 2 root root    0 Jul 17 03:09 BH
drwxr-xr-x 2 root root 4096 Jul 17 03:09 C
drwxr-xr-x 2 root root 4096 Jul 17 03:09 D
lrwxrwxrwx 1 root root    1 Jul 17 03:07 E -> B
-rw-r--r-- 2 root root    0 Jul 17 03:09 EH
lrwxrwxrwx 1 root root    1 Jul 17 03:07 F -> D
-rw-r--r-- 2 root root    0 Jul 17 03:09 G
-rw-r--r-- 2 root root    0 Jul 17 03:09 GH


I'll change bug summary and relevant information accordingly.

Development Management has reviewed and declined this request.  You may appeal
this decision by reopening this request. 

On what kernel are you testing this? I tested it on 2.6.18-96.el5debug on x86_64
and wasn't able to reproduce it -- the timestamps come up identical.

2.6.18-92.el5, as I mentioned, the bug only happens on i386.

kernel-2.6.18-97.el5 has the same problem too. The problem happens when you run
this test case the very first time. Successive runs look OK. Interesting enough,
kernel-debug is not affected. The machine I used for testing is a RHTS machine,
ibm-x3350m2-01.rhts.bos.redhat.com. The following is the debug output with
/proc/sys/sunrpc/nfs_debug enabled when the problem happened,

1.
echo "Create files and save first timestamps of files."
cd /mnt/testarea/nfs
touch A B BH G
mkdir C D
ln -s B E
ln BH EH
ln G GH
ln -s D F

NFS: nfs_fhget(0:18/0 ct=1)
NFS: nfs_fhget(0:18/14286849 ct=1)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/A)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: create(0:18/14286849), A
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286850 ct=1)
NFS: permission(0:18/14286850), mask=0x0, res=0
NFS: nfs_update_inode(0:18/14286850 ct=1 info=0x7)
NFS: dentry_delete(/A, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/B)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: create(0:18/14286849), B
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286851 ct=1)
NFS: permission(0:18/14286851), mask=0x0, res=0
NFS: nfs_update_inode(0:18/14286851 ct=1 info=0x7)
NFS: dentry_delete(/B, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/BH)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: create(0:18/14286849), BH
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286852 ct=1)
NFS: permission(0:18/14286852), mask=0x0, res=0
NFS: nfs_update_inode(0:18/14286852 ct=1 info=0x7)
NFS: dentry_delete(/BH, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/G)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: create(0:18/14286849), G
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286853 ct=1)
NFS: permission(0:18/14286853), mask=0x0, res=0
NFS: nfs_update_inode(0:18/14286853 ct=1 info=0x7)
NFS: dentry_delete(/G, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/C)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: mkdir(0:18/14286849), C
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: nfs_fhget(0:18/14286854 ct=1)
NFS: dentry_delete(/C, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/D)
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: mkdir(0:18/14286849), D
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: mtime change on server for file 0:18/14286849
NFS: nfs_fhget(0:18/14286855 ct=1)
NFS: dentry_delete(/D, 0)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/E)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/E, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: symlink(0:18/14286849, E, B)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286856 ct=1)
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/EH)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/EH, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: nfs_update_inode(0:18/14286852 ct=1 info=0x6)
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: link(/BH -> /EH)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_update_inode(0:18/14286852 ct=1 info=0x6)
NFS: dentry_delete(/EH, 8)
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/GH)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/GH, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: nfs_update_inode(0:18/14286853 ct=1 info=0x6)
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: link(/G -> /GH)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_update_inode(0:18/14286853 ct=1 info=0x6)
NFS: dentry_delete(/GH, 8)
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: lookup(/F)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/F, 0)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x3, res=0
NFS: symlink(0:18/14286849, F, D)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x7)
NFS: nfs_fhget(0:18/14286857 ct=1)
NFS: dentry_delete(/F, 8)

2.
ls -l >/tmp/1 # Without this line, the bug does not show.

NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x4, res=0
NFS: opendir(0:18/14286849)
NFS: readdir(/) starting at cookie 0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/B, 8)
NFS: dentry_delete(/F, 8)
NFS: dentry_delete(/E, 8)
NFS: dentry_delete(/EH, 8)
NFS: dentry_delete(/G, 8)
NFS: dentry_delete(/C, 8)
NFS: dentry_delete(/BH, 8)
NFS: dentry_delete(/GH, 8)
NFS: dentry_delete(/D, 8)
NFS: dentry_delete(/A, 8)
NFS: readdir(/) returns 0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286851 ct=1 info=0x8dde)
NFS: change_attr change on server for file 0:18/14286851
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286852 ct=2 info=0x11e)
NFS: change_attr change on server for file 0:18/14286852 ----> why change_attr?
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286853 ct=2 info=0x1a6)
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286854 ct=1 info=0x9aae)
NFS: change_attr change on server for file 0:18/14286854
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286855 ct=1 info=0x9bbe)
NFS: change_attr change on server for file 0:18/14286855
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286850 ct=1 info=0x355e)
NFS: change_attr change on server for file 0:18/14286850
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: readdir(/) starting at cookie 12
NFS: readdir(/) returns 0

3.
echo "Touch all files."
cd /root/nfs
touch A C E EH F G
ls -l /root/nfs /mnt/testarea/nfs

NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: permission(0:18/14286849), mask=0x4, res=0
NFS: opendir(0:18/14286849)
NFS: readdir(/) starting at cookie 0
NFS: dentry_delete(/B, 8)
NFS: dentry_delete(/F, 8)
NFS: dentry_delete(/E, 8)
NFS: dentry_delete(/EH, 8)
NFS: dentry_delete(/G, 8)
NFS: dentry_delete(/C, 8)
NFS: dentry_delete(/BH, 8)
NFS: dentry_delete(/GH, 8)
NFS: dentry_delete(/D, 8)
NFS: dentry_delete(/A, 8)
NFS: readdir(/) returns 0
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286857 ct=1 info=0x6)
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286856 ct=1 info=0x6)
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286849), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: readdir(/) starting at cookie 12
NFS: readdir(/) returns 0

If the timestamp is updated correctly, the step 3 will look like this (with
mtime change detected),

NFS: permission(0:18/14286850), mask=0x4, res=0
NFS: opendir(0:18/14286850)
NFS: readdir(/) starting at cookie 0
NFS: dentry_delete(/B, 8)
NFS: dentry_delete(/F, 8)
NFS: dentry_delete(/E, 8)
NFS: dentry_delete(/EH, 8)
NFS: dentry_delete(/G, 8)
NFS: dentry_delete(/C, 8)
NFS: dentry_delete(/BH, 8)
NFS: dentry_delete(/GH, 8)
NFS: dentry_delete(/D, 8)
NFS: dentry_delete(/A, 8)
NFS: readdir(/) returns 0
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286851 ct=1 info=0x6)
NFS: mtime change on server for file 0:18/14286851
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286851 ct=1 info=0x6)
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286857 ct=1 info=0x6)
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/F, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286855 ct=1 info=0x6)
NFS: mtime change on server for file 0:18/14286855
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286856 ct=1 info=0x6)
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/E, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/B, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286852 ct=2 info=0x6)
NFS: mtime change on server for file 0:18/14286852
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286852 ct=2 info=0x6)
NFS: dentry_delete(/EH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286853 ct=2 info=0x6)
NFS: mtime change on server for file 0:18/14286853
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286853 ct=2 info=0x6)
NFS: dentry_delete(/G, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286854 ct=1 info=0x6)
NFS: mtime change on server for file 0:18/14286854
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286854 ct=1 info=0x6)
NFS: dentry_delete(/C, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/BH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/GH, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286855 ct=1 info=0x6)
NFS: dentry_delete(/D, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: mtime change on server for file 0:18/14286849
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: dentry_delete(/A, 8)
NFS: permission(0:18/14286850), mask=0x1, res=0
NFS: nfs_update_inode(0:18/14286849 ct=1 info=0x6)
NFS: dentry_delete(/A, 8)
NFS: readdir(/) starting at cookie 12
NFS: readdir(/) returns 0

Thanks for doing that.

One thing that might be helpful is to change your "ls -l" commands to "ls -ali"
so that we can get inode numbers in the output. That may help us to correlate
the activities in these traces since we'll know the inode numbers for each inode
we're dealing with, and will have datestamps for the directory as well.


As you mention, this is strange though:

> NFS: nfs_update_inode(0:18/14286852 ct=2 info=0x11e)
> NFS: change_attr change on server for file 0:18/14286852 ----> why change_attr?

The fattr->valid (0x11e) makes no sense, and that message should only be popping
up if we're using NFSv4. Since it looks pretty clearly like your reproducer is
using NFSv3, then I suspect that the fattr->valid field isn't being properly
zeroed out before we try to populate the fattr.

That probably means we're missing a nfs_fattr_init() somewhere. I took a quick
look and don't see where it's missing, however (though there are a lot of places
that use fattr's).

Created attachment 312145 [details]
dump stack when NFS

debug patch -- dump stack when we call nfs_update_inode() and NFS_ATTR_FATTR_V4
is set...

Cai, if you could apply and test this patch it would be very helpful.
Basically:

build a nfs.ko with this patch and plug it in
turn up nfs_debug again
reproduce the problem again

...you'll want to make sure you're using NFSv3, since this will fire all of the
time with NFSv4.

...ahh and most importantly, collect dmesg output afterward. This should make it
so that we do a dump_stack() when we get one of these bogus fattr->valid values.
Having the stack trace should help pinpoint where the nfs_fattr_init is missing.

Created attachment 312154 [details]
dump stack when NFS_ATTR_FATTR_V4 is set in fattr->valid

Let's try that patch again. This one is what I intended...

I got a hold of a x86 machine and was able to reproduce this. Here's the stack
trace -- looks like 

NFS: nfs_update_inode(0:18/8838810 ct=2 info=0xfb0e)
NFS: NFS_ATTR_FATTR_V4 is set.
 [<f96174d9>] nfs_update_inode+0x152/0x619 [nfs]
 [<c042e3f2>] sigprocmask+0xb0/0xce
 [<f9617a57>] nfs_refresh_inode+0x38/0x1aa [nfs]
 [<f9623d46>] nfs3_proc_getacl+0x1bc/0x2f5 [nfs]
 [<f96240e3>] nfs3_getxattr+0x59/0xad [nfs]
 [<f962408a>] nfs3_getxattr+0x0/0xad [nfs]
 [<c048c887>] vfs_getxattr+0x6f/0xd0
 [<c048c95d>] getxattr+0x75/0xbe
 [<c0485156>] dput+0x22/0xed
 [<c047e591>] __link_path_walk+0xbfa/0xd33
 [<f961e3ac>] nfs_wait_on_requests_locked+0x91/0xa5 [nfs]
 [<c04889ee>] mntput_no_expire+0x11/0x6a
 [<c047e77d>] link_path_walk+0xb3/0xbd
 [<c044b245>] audit_syscall_entry+0x14b/0x17d
 [<c0407efa>] do_syscall_trace+0xab/0xb1
 [<c047eae0>] do_path_lookup+0x20e/0x25e
 [<c047f22d>] __user_walk_fd+0x32/0x3a
 [<c048ca21>] sys_getxattr+0x36/0x48
 [<c044b245>] audit_syscall_entry+0x14b/0x17d
 [<c0407efa>] do_syscall_trace+0xab/0xb1
 [<c0404eff>] syscall_call+0x7/0xb
 =======================

...looks like nfs3_proc_getacl() needs a nfs_fattr_init() call.

nfs3_proc_setacls also needs to be fixed.

This appears to be an upstream and RHEL4 bug as well. I'll poke around a bit and
see if I can find other places that fattrs are used unintialized.

Created attachment 312167 [details]
patch -- properly initialize fattrs in nfs3_proc_getacl and nfs3_proc_setacls

I believe this patch should fix the problem. We're not initializing the fattr
struct before using it, so the "valid" field ends up being set to whatever was
on the stack.

I'll also need to send the patch upstream, but I don't expect any real debate
on this there. RHEL4 also has the same problem, so I'll plan to clone this for
it as well.

Cai, could you test this patch and confirm whether it fixes the problem?

This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux maintenance release.  Product Management has requested
further review of this request by Red Hat Engineering, for potential
inclusion in a Red Hat Enterprise Linux Update release for currently deployed
products.  This request is not yet committed for inclusion in an Update
release.

Patch pushed upstream to Trond and linux-nfs mailing list:

Subject: [PATCH] NFS: missing nfs_fattr_init in nfs3_proc_getacl and
nfs3_proc_setacls

Confirmed the patch (applied to .96 Kernel) fixed the problem. Thanks.

Thanks for testing it, Cai. At this point, I'm awaiting feedback from upstream
maintainer.

Patch sent to upstream maintainer twice with no response. I've just sent it a third time, if we don't get a response by internal patch submission deadline, I'll plan to propose it internally and revise it if need be when Trond takes it in.

in kernel-2.6.18-107.el5
You can download this test kernel from http://people.redhat.com/dzickus/el5

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2009-0225.html