strange put_rpccred() handling

DISCUSSION OGAWA Hirofumi 2 participants 4 messages Mar 27, 2011

Subsystems (2)

NFS client NFS server

lore

Share & tools

lore

OGAWA Hirofumi

author

2011-03-27 15:32 UTC #0 lore raw

Hi,

BUG: atomic_dec_and_test(): -1: atomic counter underflow at:
Pid: 2827, comm: mount.nfs Not tainted 2.6.38 #1
Call Trace:
 [<ffffffffa02223a0>] ? put_rpccred+0x44/0x14e [sunrpc]
 [<ffffffffa021bbe9>] ? rpc_ping+0x4e/0x58 [sunrpc]
 [<ffffffffa021c4a5>] ? rpc_create+0x481/0x4fc [sunrpc]
 [<ffffffffa022298a>] ? rpcauth_lookup_credcache+0xab/0x22d [sunrpc]
 [<ffffffffa028be8c>] ? nfs_create_rpc_client+0xa6/0xeb [nfs]
 [<ffffffffa028c660>] ? nfs4_set_client+0xc2/0x1f9 [nfs]
 [<ffffffffa028cd3c>] ? nfs4_create_server+0xf2/0x2a6 [nfs]
 [<ffffffffa0295d07>] ? nfs4_remote_mount+0x4e/0x14a [nfs]
 [<ffffffff810dd570>] ? vfs_kern_mount+0x6e/0x133
 [<ffffffffa029605a>] ? nfs_do_root_mount+0x76/0x95 [nfs]
 [<ffffffffa029643d>] ? nfs4_try_mount+0x56/0xaf [nfs]
 [<ffffffffa0297434>] ? nfs_get_sb+0x435/0x73c [nfs]
 [<ffffffff810dd59b>] ? vfs_kern_mount+0x99/0x133
 [<ffffffff810dd693>] ? do_kern_mount+0x48/0xd8
 [<ffffffff810f5b75>] ? do_mount+0x6da/0x741
 [<ffffffff810f5c5f>] ? sys_mount+0x83/0xc0
 [<ffffffff8100293b>] ? system_call_fastpath+0x16/0x1b

This is not oops, and debug code is not in vanilla. This debug code is simple - detects atomic_dec_and_test() underflow.

Well, so, I think this is real bug of nfs codes somewhere. With some review, the code

rpc_call_sync()
rpc_run_task
rpc_execute()
__rpc_execute()
rpc_release_task()
rpc_release_resources_task()
put_rpccred() <= release cred
rpc_put_task
rpc_do_put_task()
rpc_release_resources_task()
put_rpccred() <= release cred again

seems to be release cred unintendedly.

static void rpc_release_resources_task(struct rpc_task *task)

{
	if (task->tk_rqstp)
		xprt_release(task);
	if (task->tk_msg.rpc_cred) {
		put_rpccred(task->tk_msg.rpc_cred);
		task->tk_msg.rpc_cred = NULL;
	}
	rpc_task_release_client(task);
}

The above change may fix the problem though, I don't know the codes what want to do actually. And I guess this is not right fix, because the path is looks strange - on early stage, __rpc_execute() calls rpc_release_task() explicitly.

Thanks.

Signature · 1 line

OGAWA Hirofumi <[email protected]>

Trond Myklebust

2011-03-27 15:34 UTC #1 lore raw

Quoted 54 lines · OGAWA Hirofumi

Hi,

BUG: atomic_dec_and_test(): -1: atomic counter underflow at:
Pid: 2827, comm: mount.nfs Not tainted 2.6.38 #1
Call Trace:
 [<ffffffffa02223a0>] ? put_rpccred+0x44/0x14e [sunrpc]
 [<ffffffffa021bbe9>] ? rpc_ping+0x4e/0x58 [sunrpc]
 [<ffffffffa021c4a5>] ? rpc_create+0x481/0x4fc [sunrpc]
 [<ffffffffa022298a>] ? rpcauth_lookup_credcache+0xab/0x22d [sunrpc]
 [<ffffffffa028be8c>] ? nfs_create_rpc_client+0xa6/0xeb [nfs]
 [<ffffffffa028c660>] ? nfs4_set_client+0xc2/0x1f9 [nfs]
 [<ffffffffa028cd3c>] ? nfs4_create_server+0xf2/0x2a6 [nfs]
 [<ffffffffa0295d07>] ? nfs4_remote_mount+0x4e/0x14a [nfs]
 [<ffffffff810dd570>] ? vfs_kern_mount+0x6e/0x133
 [<ffffffffa029605a>] ? nfs_do_root_mount+0x76/0x95 [nfs]
 [<ffffffffa029643d>] ? nfs4_try_mount+0x56/0xaf [nfs]
 [<ffffffffa0297434>] ? nfs_get_sb+0x435/0x73c [nfs]
 [<ffffffff810dd59b>] ? vfs_kern_mount+0x99/0x133
 [<ffffffff810dd693>] ? do_kern_mount+0x48/0xd8
 [<ffffffff810f5b75>] ? do_mount+0x6da/0x741
 [<ffffffff810f5c5f>] ? sys_mount+0x83/0xc0
 [<ffffffff8100293b>] ? system_call_fastpath+0x16/0x1b

This is not oops, and debug code is not in vanilla. This debug code is simple - detects atomic_dec_and_test() underflow.

Well, so, I think this is real bug of nfs codes somewhere. With some review, the code

seems to be release cred unintendedly.

static void rpc_release_resources_task(struct rpc_task *task)

{
	if (task->tk_rqstp)
		xprt_release(task);
	if (task->tk_msg.rpc_cred) {
		put_rpccred(task->tk_msg.rpc_cred);
		task->tk_msg.rpc_cred = NULL;
	}
	rpc_task_release_client(task);
}

Quoted 4 lines

The above change may fix the problem though, I don't know the codes what want to do actually. And I guess this is not right fix, because the path is looks strange - on early stage, __rpc_execute() calls rpc_release_task() explicitly.

Argh! You are completely correct. The intention was that rpc_release_resources_task() should be able to be called more than once, which means that we have to set task->tk_msg.rpc_cred to NULL after freeing the cred. I've no idea why I missed that when I cleaned up that code.

Thanks for debugging this!

Signature · 6 lines

Trond Myklebust
Linux NFS client maintainer

NetApp
[email protected]
www.netapp.com

Trond Myklebust

2011-03-27 15:55 UTC #2 lore raw

In reply to OGAWA Hirofumi

Quoted 44 lines · OGAWA Hirofumi

Hi,
BUG: atomic_dec_and_test(): -1: atomic counter underflow at:
Pid: 2827, comm: mount.nfs Not tainted 2.6.38 #1
Call Trace:
 [<ffffffffa02223a0>] ? put_rpccred+0x44/0x14e [sunrpc]
 [<ffffffffa021bbe9>] ? rpc_ping+0x4e/0x58 [sunrpc]
 [<ffffffffa021c4a5>] ? rpc_create+0x481/0x4fc [sunrpc]
 [<ffffffffa022298a>] ? rpcauth_lookup_credcache+0xab/0x22d [sunrpc]
 [<ffffffffa028be8c>] ? nfs_create_rpc_client+0xa6/0xeb [nfs]
 [<ffffffffa028c660>] ? nfs4_set_client+0xc2/0x1f9 [nfs]
 [<ffffffffa028cd3c>] ? nfs4_create_server+0xf2/0x2a6 [nfs]
 [<ffffffffa0295d07>] ? nfs4_remote_mount+0x4e/0x14a [nfs]
 [<ffffffff810dd570>] ? vfs_kern_mount+0x6e/0x133
 [<ffffffffa029605a>] ? nfs_do_root_mount+0x76/0x95 [nfs]
 [<ffffffffa029643d>] ? nfs4_try_mount+0x56/0xaf [nfs]
 [<ffffffffa0297434>] ? nfs_get_sb+0x435/0x73c [nfs]
 [<ffffffff810dd59b>] ? vfs_kern_mount+0x99/0x133
 [<ffffffff810dd693>] ? do_kern_mount+0x48/0xd8
 [<ffffffff810f5b75>] ? do_mount+0x6da/0x741
 [<ffffffff810f5c5f>] ? sys_mount+0x83/0xc0
 [<ffffffff8100293b>] ? system_call_fastpath+0x16/0x1b
This is not oops, and debug code is not in vanilla. This debug code is simple - detects atomic_dec_and_test() underflow.
Well, so, I think this is real bug of nfs codes somewhere. With some review, the code
rpc_call_sync()
rpc_run_task
rpc_execute()
__rpc_execute()
rpc_release_task()
rpc_release_resources_task()
put_rpccred() <= release cred
rpc_put_task
rpc_do_put_task()
rpc_release_resources_task()
put_rpccred() <= release cred again
seems to be release cred unintendedly.
static void rpc_release_resources_task(struct rpc_task *task)

Quoted 9 lines

{
	if (task->tk_rqstp)
		xprt_release(task);
	if (task->tk_msg.rpc_cred) {
		put_rpccred(task->tk_msg.rpc_cred);
		task->tk_msg.rpc_cred = NULL;
	}
	rpc_task_release_client(task);
}

May I add a signed-off-by from you, and just push the above fix to Linus?

Cheers
Trond

Signature · 6 lines

Trond Myklebust
Linux NFS client maintainer

NetApp
[email protected]
www.netapp.com

OGAWA Hirofumi

author

2011-03-27 16:15 UTC #3 lore raw

Quoted 55 lines · Trond Myklebust

Quoted 44 lines · OGAWA Hirofumi
Hi,
BUG: atomic_dec_and_test(): -1: atomic counter underflow at:
Pid: 2827, comm: mount.nfs Not tainted 2.6.38 #1
Call Trace:
 [<ffffffffa02223a0>] ? put_rpccred+0x44/0x14e [sunrpc]
 [<ffffffffa021bbe9>] ? rpc_ping+0x4e/0x58 [sunrpc]
 [<ffffffffa021c4a5>] ? rpc_create+0x481/0x4fc [sunrpc]
 [<ffffffffa022298a>] ? rpcauth_lookup_credcache+0xab/0x22d [sunrpc]
 [<ffffffffa028be8c>] ? nfs_create_rpc_client+0xa6/0xeb [nfs]
 [<ffffffffa028c660>] ? nfs4_set_client+0xc2/0x1f9 [nfs]
 [<ffffffffa028cd3c>] ? nfs4_create_server+0xf2/0x2a6 [nfs]
 [<ffffffffa0295d07>] ? nfs4_remote_mount+0x4e/0x14a [nfs]
 [<ffffffff810dd570>] ? vfs_kern_mount+0x6e/0x133
 [<ffffffffa029605a>] ? nfs_do_root_mount+0x76/0x95 [nfs]
 [<ffffffffa029643d>] ? nfs4_try_mount+0x56/0xaf [nfs]
 [<ffffffffa0297434>] ? nfs_get_sb+0x435/0x73c [nfs]
 [<ffffffff810dd59b>] ? vfs_kern_mount+0x99/0x133
 [<ffffffff810dd693>] ? do_kern_mount+0x48/0xd8
 [<ffffffff810f5b75>] ? do_mount+0x6da/0x741
 [<ffffffff810f5c5f>] ? sys_mount+0x83/0xc0
 [<ffffffff8100293b>] ? system_call_fastpath+0x16/0x1b
This is not oops, and debug code is not in vanilla. This debug code is simple - detects atomic_dec_and_test() underflow.
Well, so, I think this is real bug of nfs codes somewhere. With some review, the code
rpc_call_sync()
rpc_run_task
rpc_execute()
__rpc_execute()
rpc_release_task()
rpc_release_resources_task()
put_rpccred() <= release cred
rpc_put_task
rpc_do_put_task()
rpc_release_resources_task()
put_rpccred() <= release cred again
seems to be release cred unintendedly.
static void rpc_release_resources_task(struct rpc_task *task)
Quoted 9 lines
{
	if (task->tk_rqstp)
		xprt_release(task);
	if (task->tk_msg.rpc_cred) {
		put_rpccred(task->tk_msg.rpc_cred);
		task->tk_msg.rpc_cred = NULL;
	}
	rpc_task_release_client(task);
}

Quoted 2 lines

May I add a signed-off-by from you, and just push the above fix to Linus?

Yes, of course.

Signed-off-by OGAWA Hirofumi <[email protected]>

Signature · 1 line

OGAWA Hirofumi <[email protected]>