Bug 455917

Summary:	fattr structs being used uninitialized in nfs3_proc_getacl and nfs3_proc_setacls
Product:	Red Hat Enterprise Linux 4	Reporter:	Jeff Layton <jlayton>
Component:	kernel	Assignee:	Jeff Layton <jlayton>
Status:	CLOSED ERRATA	QA Contact:	Martin Jenner <mjenner>
Severity:	high	Docs Contact:
Priority:	high
Version:	4.7	CC:	duck, qcai, staubach, steved
Target Milestone:	rc	Keywords:	Reopened
Target Release:	---
Hardware:	i386
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2009-05-18 19:19:41 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	453711
Bug Blocks:	461297

Description Jeff Layton 2008-07-18 19:08:11 UTC

+++ This bug was initially created as a clone of Bug #453711 +++
-- Additional comment from qcai on 2008-07-17 03:18 EST --
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.

-- Additional comment from pm-rhel on 2008-07-17 03:18 EST --
Development Management has reviewed and declined this request.  You may appeal
this decision by reopening this request. 

-- Additional comment from jlayton on 2008-07-17 16:39 EST --
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.


-- Additional comment from qcai on 2008-07-17 19:58 EST --
2.6.18-92.el5, as I mentioned, the bug only happens on i386.

-- Additional comment from qcai on 2008-07-17 22:25 EST --
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


-- Additional comment from jlayton on 2008-07-18 09:51 EST --
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).


-- Additional comment from jlayton on 2008-07-18 11:07 EST --
Created an attachment (id=312145)
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.


-- Additional comment from jlayton on 2008-07-18 11:09 EST --
...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.


-- Additional comment from jlayton on 2008-07-18 13:18 EST --
Created an attachment (id=312154)
dump stack when NFS_ATTR_FATTR_V4 is set in fattr->valid

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


-- Additional comment from jlayton on 2008-07-18 14:32 EST --
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.


-- Additional comment from jlayton on 2008-07-18 14:40 EST --
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.


-- Additional comment from jlayton on 2008-07-18 15:02 EST --
Created an attachment (id=312167)
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.

Comment 1 RHEL Program Management 2008-08-07 14:24:55 UTC

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.

Comment 2 RHEL Program Management 2008-09-03 13:04:23 UTC

Updating PM score.

Comment 4 Vivek Goyal 2008-10-28 12:56:17 UTC

Committed in 78.16.EL . RPMS are available at http://people.redhat.com/vgoyal/rhel4/

Comment 7 errata-xmlrpc 2009-05-18 19:19:41 UTC

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-1024.html