Bug 633540

Created attachment 447070 [details]
dmesg from grant-01

Created attachment 447073 [details]
dmesg from grant-02

Created attachment 447074 [details]
dmesg from grant-03

I wonder whether fs/nfsd/nfs4state.c:nfs4_upgrade_open() needs a call into the ima code?

In upstream I removed the need for nfs4_upgrade_open entirely; backported patch attached (on rhel6 compile-tested only).

Created attachment 447353 [details]
backport of upstream open-file-handling patches from 2.6.36

This indicates that from a struct file was created (everything in the kernel uses alloc_file these days right?) the fmode was set RO but the struct file was later switch to be writable.

I'm not sure that is valid behaviour, is it?

It's not really valid, but the nfsv4 server code has gotten away with it for a long time (take a look at fs/nfsd/nfs4state.c:nfs4_upgrade_open()).

I recently fixed upstream so it doesn't do that any more.  So (if that's the cause of this problem) our choices are: (1) add whatever ima hook we need to nfs4_upgrade_open() to fix up the accounting (you'd probably know better than me what that would be), or (2) backport those upstream changes.

I'd actually prefer (2), though it's more intrusive, as those changes fix some other problems as well, and as we already seem to be trying to follow upstream pretty aggressively to facilitate backporting some new features during rhel6.

This is fairly easy to reproduce with our tests. Bumping the priority...

Would it be easy for you to run your tests on a kernel with the attached backport applied?

Just to get an idea of the severity: how bad are the consequences of an ima imbalance (beyond just getting the logs spammed)?

The spam is mostly harmless.  It means that IMA isn't correct over NFS, but I doubt anyone is going to care about that since I don't know anyone actually using IMA functionality ATM, and even if they did, it's unlikely to be interested in files exported via NFS to other machines (It's typically only interested in system files)

*** Bug 600152 has been marked as a duplicate of this bug. ***

As a workaround is there a simple way just to keep the warnings out of the logs?

Eric, is this something that we can do (https://bugzilla.redhat.com/show_bug.cgi?id=633540#c13)?

Should we just close this?

No, there is going to be one set of spam per boot and we can't get rid of it other than fixing NFS....

6.1 kernels now include revisions of the attached patches, so these messages should be gone; reopen if not.

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.

Reopening after seeing the following issues on the nfs client.

[root@flea-10 ~]# uname -ar
Linux flea-10 2.6.32-71.el6.x86_64 #1 SMP Wed Sep 1 01:33:01 EDT 2010 x86_64 x86_64 x86_64 GNU/Linux

Slow work thread pool: Starting up
Slow work thread pool: Ready
FS-Cache: Loaded
FS-Cache: Netfs 'nfs' registered for caching


nfs4_reclaim_open_state: Lock reclaim failed!
nfs4_reclaim_open_state: Lock reclaim failed!
INFO: task xdoio:1734 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xdoio         D 0000000000000002     0  1734   1723 0x00000080
 ffff88003c861a88 0000000000000086 ffff8800ffffffff 00000aa0fed4a3ce
 ffff88003c861a18 ffff88003c86cf30 0000000000029b78 000000010041a2be
 ffff88003cdbd0a8 ffff88003c861fd8 0000000000010518 ffff88003cdbd0a8
Call Trace:
 [<ffffffff8109b9a9>] ? ktime_get_ts+0xa9/0xe0
 [<ffffffff8110c060>] ? sync_page+0x0/0x50
 [<ffffffff814c8a23>] io_schedule+0x73/0xc0
 [<ffffffff8110c09d>] sync_page+0x3d/0x50
 [<ffffffff814c929f>] __wait_on_bit+0x5f/0x90
 [<ffffffff8110c253>] wait_on_page_bit+0x73/0x80
 [<ffffffff81091ce0>] ? wake_bit_function+0x0/0x50
 [<ffffffffa02c7e64>] nfs_wb_page+0xb4/0xd0 [nfs]
 [<ffffffffa02b68de>] nfs_launder_page+0x4e/0x80 [nfs]
 [<ffffffff811233c6>] invalidate_inode_pages2_range+0x2f6/0x380
 [<ffffffff81123467>] invalidate_inode_pages2+0x17/0x20
 [<ffffffffa02baa48>] nfs_revalidate_mapping+0x128/0x170 [nfs]
 [<ffffffffa02b7897>] nfs_file_read+0x77/0x130 [nfs]
 [<ffffffff8116c65a>] do_sync_read+0xfa/0x140
 [<ffffffff81091ca0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff81167349>] ? do_huge_pmd_anonymous_page+0xc9/0x360
 [<ffffffff8120bf4b>] ? selinux_file_permission+0xfb/0x150
 [<ffffffff811ff3b6>] ? security_file_permission+0x16/0x20
 [<ffffffff8116d085>] vfs_read+0xb5/0x1a0
 [<ffffffff810d40a2>] ? audit_syscall_entry+0x272/0x2a0
 [<ffffffff8116d1c1>] sys_read+0x51/0x90
 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b
INFO: task xdoio:1734 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xdoio         D 0000000000000002     0  1734   1723 0x00000080
 ffff88003c861a88 0000000000000086 ffff8800ffffffff 00000aa0fed4a3ce
 ffff88003c861a18 ffff88003c86cf30 0000000000029b78 000000010041a2be
 ffff88003cdbd0a8 ffff88003c861fd8 0000000000010518 ffff88003cdbd0a8
Call Trace:
 [<ffffffff8109b9a9>] ? ktime_get_ts+0xa9/0xe0
 [<ffffffff8110c060>] ? sync_page+0x0/0x50
 [<ffffffff814c8a23>] io_schedule+0x73/0xc0
 [<ffffffff8110c09d>] sync_page+0x3d/0x50
 [<ffffffff814c929f>] __wait_on_bit+0x5f/0x90
 [<ffffffff8110c253>] wait_on_page_bit+0x73/0x80
 [<ffffffff81091ce0>] ? wake_bit_function+0x0/0x50
 [<ffffffffa02c7e64>] nfs_wb_page+0xb4/0xd0 [nfs]
 [<ffffffffa02b68de>] nfs_launder_page+0x4e/0x80 [nfs]
 [<ffffffff811233c6>] invalidate_inode_pages2_range+0x2f6/0x380
 [<ffffffff81123467>] invalidate_inode_pages2+0x17/0x20
 [<ffffffffa02baa48>] nfs_revalidate_mapping+0x128/0x170 [nfs]
 [<ffffffffa02b7897>] nfs_file_read+0x77/0x130 [nfs]
 [<ffffffff8116c65a>] do_sync_read+0xfa/0x140
 [<ffffffff81091ca0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff81167349>] ? do_huge_pmd_anonymous_page+0xc9/0x360
 [<ffffffff8120bf4b>] ? selinux_file_permission+0xfb/0x150
 [<ffffffff811ff3b6>] ? security_file_permission+0x16/0x20
 [<ffffffff8116d085>] vfs_read+0xb5/0x1a0
 [<ffffffff810d40a2>] ? audit_syscall_entry+0x272/0x2a0
 [<ffffffff8116d1c1>] sys_read+0x51/0x90
 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b

Still seeing issues on multiple cluster during nfsv4 recovery.

Apr 14 16:52:24 grant-03 rgmanager[2237]: Service service:nfs1 started
------------[ cut here ]------------
kernel BUG at fs/nfsd/nfs4state.c:390!
invalid opcode: 0000 [#1] SMP
last sysfs file: /sys/devices/pci0000:00/0000:00:08.0/0000:01:00.0/net/eth0/broadcast
CPU 0
Modules linked in: nfsd lockd nfs_acl auth_rpcgss exportfs ext3 jbd dlm configfs sunrpc c]

Modules linked in: nfsd lockd nfs_acl auth_rpcgss exportfs ext3 jbd dlm configfs sunrpc c]
Pid: 3555, comm: nfsd Not tainted 2.6.32-130.el6.x86_64 #1 PowerEdge SC1435
RIP: 0010:[<ffffffffa04d32b5>]  [<ffffffffa04d32b5>] free_generic_stateid+0x35/0xb0 [nfsd]
RSP: 0018:ffff8801198d9b00  EFLAGS: 00010297
RAX: 0000000000000000 RBX: ffff880119f85f38 RCX: ffff8801198d9ae8
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff8801198d9b0c
RBP: ffff8801198d9b20 R08: ffff880119f85f58 R09: 0000000000000000
R10: 0000000000000010 R11: 0000000000000000 R12: ffff8801198d7dd8
R13: ffff8801198d7e10 R14: ffff8801198d7dd8 R15: ffff880119f85740
FS:  00007f6ce4131700(0000) GS:ffff880028200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 00007f6ce413c000 CR3: 0000000218e85000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process nfsd (pid: 3555, threadinfo ffff8801198d8000, task ffff88011a580a80)
Stack:
 ffff8801198d9b20 00000000a04cee88 ffff880119f85f38 ffff8801198d7dd8
<0> ffff8801198d9b50 ffffffffa04d3389 0000000000000000 ffff88021a1591a0
<0> 000000001d270000 ffff88021a15a040 ffff8801198d9d80 ffffffffa04d3a5d
Call Trace:
 [<ffffffffa04d3389>] release_lockowner+0x59/0xb0 [nfsd]
 [<ffffffffa04d3a5d>] nfsd4_lock+0x4cd/0x7e0 [nfsd]
 [<ffffffffa04bda06>] ? nfsd_setuser+0x126/0x2c0 [nfsd]
 [<ffffffffa04b5852>] ? nfsd_setuser_and_check_port+0x62/0xb0 [nfsd]
 [<ffffffffa04b5a07>] ? fh_verify+0x167/0x650 [nfsd]
 [<ffffffffa04c4f01>] nfsd4_proc_compound+0x3d1/0x490 [nfsd]
 [<ffffffffa04b243e>] nfsd_dispatch+0xfe/0x240 [nfsd]
 [<ffffffffa03bf4d4>] svc_process_common+0x344/0x640 [sunrpc]
 [<ffffffff8105d710>] ? default_wake_function+0x0/0x20
 [<ffffffffa03bfb10>] svc_process+0x110/0x160 [sunrpc]
 [<ffffffffa04b2b62>] nfsd+0xc2/0x160 [nfsd]
 [<ffffffffa04b2aa0>] ? nfsd+0x0/0x160 [nfsd]
 [<ffffffff8108de16>] kthread+0x96/0xa0
 [<ffffffff8100c1ca>] child_rip+0xa/0x20
 [<ffffffff8108dd80>] ? kthread+0x0/0xa0
 [<ffffffff8100c1c0>] ? child_rip+0x0/0x20
Code: 10 0f 1f 44 00 00 48 8b 77 60 48 89 fb 48 8d 7d ec e8 b0 c1 ff ff 8b 45 ec 83 e0 03
RIP  [<ffffffffa04d32b5>] free_generic_stateid+0x35/0xb0 [nfsd]
 RSP <ffff8801198d9b00>
---[ end trace 536ae40f35a0eb0d ]---
Apr 14 16:52:27 Kernel panic - not syncing: Fatal exception
grant-03 kernel:Pid: 3555, comm: nfsd Tainted: G      D    ----------------   2.6.32-130.1
 ------------[ cCall Trace:
ut here ]------- [<ffffffff814da981>] ? panic+0x78/0x143
-----
 [<ffffffff814de9c4>] ? oops_end+0xe4/0x100
 [<ffffffff8100f2fb>] ? die+0x5b/0x90
 [<ffffffff814de294>] ? do_trap+0xc4/0x160
 [<ffffffff8100ceb5>] ? do_invalid_op+0x95/0xb0
 [<ffffffffa04d32b5>] ? free_generic_stateid+0x35/0xb0 [nfsd]

Bugs reported in comments 21 and 22 are very different from the original bug, and from each other (#21 looks like a client bug, and #22 like a server bug).  Please open new bugs for those rather than reopening this one.

*** This bug has been marked as a duplicate of bug 663448 ***

FYI - I opened 697029 and 697032 for the issues listed in comments #21 and #22.

dang bugzilla, I didn't mean to re-open this.

*** This bug has been marked as a duplicate of bug 663448 ***