Re: CIFS endless console spammage in 2.6.38.7

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Sat, 4 Jun 2011 07:19:23 -0400
Jeff Layton <jlayton@xxxxxxxxxx> wrote:

> On Fri, 03 Jun 2011 22:03:43 -0700
> Ben Greear <greearb@xxxxxxxxxxxxxxx> wrote:
> 
> > On 06/03/2011 06:42 PM, Jeff Layton wrote:
> > > On Fri, 03 Jun 2011 14:01:11 -0700
> > > Ben Greear<greearb@xxxxxxxxxxxxxxx>  wrote:
> > >
> > >> Ok, we had some luck.  Here's the backtrace and attending dmesg
> > >> output.  The filer has been doing failover, but it has not gone
> > >> into a failed state...so, the system *should* be able to reconnect.
> > >>
> > >> We have the system in the failed state now and will leave it that way
> > >> for a bit in case you have some commands you'd like me to run.
> > >>
> > >> Aside from the hung cifs processes (anything accessing those mounts
> > >> gets into the D state), the system seems fine.
> > >>
> > >>
> > >> CIFS VFS: Unexpected lookup error -112
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Unexpected lookup error -11
> > >> CIFS VFS: Unexpected lookup error -112
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Unexpected lookup error -112
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Unexpected lookup error -11
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: Reconnecting tcp session
> > >> CIFS VFS: need to reconnect in sendv here
> > >> ------------[ cut here ]------------
> > >> WARNING: at /home/greearb/git/linux-2.6.dev.38.y/fs/cifs/transport.c:137 smb_sendv+0x7a/0x2cf [cifs]()
> > >> BUG: unable to handle kernel
> > >> Hardware name: X8ST3
> > >> NULL pointer dereference
> > >> Modules linked in: at 0000000000000020
> > >>    be2iscsi
> > >> IP: iscsi_boot_sysfs [<ffffffff81356230>] __sock_recvmsg_nosec+0x12/0x6e
> > >>    bnx2iPGD 0  cnic
> > >>    uio
> > >> Oops: 0000 [#1]  cxgb3iPREEMPT  libcxgbiSMP  cxgb3
> > >>    mdio
> > >> last sysfs file: /sys/devices/platform/host10/session7/target10:0:0/10:0:0:0/block/sde/sde1/stat
> > >>    ib_iserCPU 2  rdma_cm
> > >> Modules linked in: ib_cm be2iscsi iw_cm iscsi_boot_sysfs ib_sa bnx2i ib_mad cnic ib_core uio ib_addr cxgb3i md4 libcxgbi nls_utf8 cxgb3 cifs mdio xt_TPROXY
> > >> ib_iser rdma_cm nf_tproxy_core ib_cm xt_socket iw_cm ib_sa ip6_tables ib_mad ib_core nf_defrag_ipv6 ib_addr md4 nls_utf8 xt_connlimit cifs xt_TPROXY
> > >> nf_tproxy_core xt_socket ip6_tables nf_defrag_ipv6 xt_connlimit 8021q garp bridge stp llc fuse macvlan wanlink(P) pktgen iscsi_tcp libiscsi_tcp libiscsi
> > >> scsi_transport_iscsi nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6 uinput i2c_i801 e1000e 8021q i2c_core garp igb bridge ioatdma stp iTCO_wdt llc
> > >> i7core_edac fuse iTCO_vendor_support macvlan pcspkr wanlink(P) dca pktgen edac_core iscsi_tcp microcode [last unloaded: ipt_addrtype] libiscsi_tcp
> > >>    libiscsi
> > >>    scsi_transport_iscsi
> > >> Pid: 5047, comm: cifsd Tainted: P            2.6.38.8+ #12 nfs  lockdSupermicro X8ST3 fscache/X8ST3 nfs_acl
> > >>    auth_rpcgss
> > >> RIP: 0010:[<ffffffff81356230>]  [<ffffffff81356230>] __sock_recvmsg_nosec+0x12/0x6e
> > >>    sunrpc
> > >> RSP: 0018:ffff8802e64e5bc0  EFLAGS: 00010286
> > >>    ipv6
> > >> RAX: 0000000000000000 RBX: ffff8802e64e5c40 RCX: 0000000000000004
> > >>    uinput
> > >> RDX: ffff8802e64e5e40 RSI: 0000000000000000 RDI: ffff8802e64e5c40
> > >>    i2c_i801
> > >> RBP: ffff8802e64e5bf0 R08: 0000000000000000 R09: 0000000000000000
> > >> R10: ffff8802e64e5d80 R11: ffff8802e64e5e40 R12: ffff8802e64e5d10
> > >>    e1000e
> > >> R13: 0000000000000000 R14: ffff8802e64e5c40 R15: ffff8802e6429f80
> > >>    i2c_core
> > >> FS:  0000000000000000(0000) GS:ffff8800df440000(0000) knlGS:0000000000000000
> > >>    igb
> > >> CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> > >>    ioatdma
> > >> CR2: 0000000000000020 CR3: 0000000001803000 CR4: 00000000000006e0
> > >>    iTCO_wdt
> > >> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > >>    i7core_edac
> > >> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> > >>    iTCO_vendor_supportProcess cifsd (pid: 5047, threadinfo ffff8802e64e4000, task ffff88030482d880)
> > >>    pcspkr
> > >> Stack:
> > >>    dca ffff8802e64e5c10 edac_core ffffffff81039b72 microcode ffff880200000001 [last unloaded: ipt_addrtype] ffff880305a40fc8
> > >>
> > >>    ffff8802e64e5e40Pid: 4754, comm: btserver Tainted: P            2.6.38.8+ #12
> > >>    0000000000000004Call Trace:
> > >>    ffff8802e64e5c30 ffffffff8135792c
> > >>    0000000000000000 0000000000000000 [<ffffffff8104556a>] ? warn_slowpath_common+0x80/0x98
> > >>    ffff8802e64e5c40 ffffffffffffffff [<ffffffff81045597>] ? warn_slowpath_null+0x15/0x17
> > >>
> > >> Call Trace:
> > >>    [<ffffffffa0330a2c>] ? smb_sendv+0x7a/0x2cf [cifs]
> > >>    [<ffffffff81039b72>] ? select_idle_sibling+0xec/0x127
> > >>    [<ffffffff8135792c>] __sock_recvmsg+0x49/0x54
> > >>    [<ffffffff81357e96>] sock_recvmsg+0xa6/0xbf
> > >>    [<ffffffff8103fde4>] ? get_parent_ip+0x11/0x42
> > >>    [<ffffffff81041ee4>] ? try_to_wake_up+0x1ad/0x1c8
> > >>    [<ffffffff8103fde4>] ? get_parent_ip+0x11/0x42
> > >>    [<ffffffff81041f0c>] ? default_wake_function+0xd/0xf
> > >>    [<ffffffff8105c7e0>] ? autoremove_wake_function+0x11/0x34
> > >>    [<ffffffffa0330ca2>] ? smb_send+0x21/0x23 [cifs]
> > >>    [<ffffffff8103fde4>] ? get_parent_ip+0x11/0x42
> > >>    [<ffffffff814164ec>] ? sub_preempt_count+0x92/0xa5
> > >>    [<ffffffffa03311d1>] ? SendReceive+0x13f/0x317 [cifs]
> > >>    [<ffffffff814133f8>] ? _raw_spin_unlock_irqrestore+0x3a/0x47
> > >>    [<ffffffff810382c6>] ? __wake_up+0x3f/0x48
> > >>    [<ffffffffa031d839>] ? CIFSSMBNegotiate+0x191/0x766 [cifs]
> > >>    [<ffffffff81357ee4>] kernel_recvmsg+0x35/0x41
> > >>    [<ffffffff81412526>] ? __mutex_lock_common+0x358/0x3bc
> > >>    [<ffffffffa0321d20>] cifs_demultiplex_thread+0x21e/0xcd9 [cifs]
> > >>    [<ffffffffa031fd7b>] ? cifs_negotiate_protocol+0x37/0x87 [cifs]
> > >>    [<ffffffff8103fde4>] ? get_parent_ip+0x11/0x42
> > >>    [<ffffffff8141259e>] ? __mutex_lock_slowpath+0x14/0x16
> > >>    [<ffffffff8103838e>] ? need_resched+0x1e/0x28
> > >>    [<ffffffffa0315fed>] ? cifs_reconnect_tcon+0x19a/0x2c9 [cifs]
> > >>    [<ffffffffa0321b02>] ? cifs_demultiplex_thread+0x0/0xcd9 [cifs]
> > >>    [<ffffffff8105c7cf>] ? autoremove_wake_function+0x0/0x34
> > >>    [<ffffffffa0321b02>] ? cifs_demultiplex_thread+0x0/0xcd9 [cifs]
> > >>    [<ffffffff8105c3bf>] kthread+0x7d/0x85
> > >>    [<ffffffffa031af96>] ? small_smb_init+0x27/0x70 [cifs]
> > >>    [<ffffffff8100b8e4>] kernel_thread_helper+0x4/0x10
> > >>    [<ffffffffa031c0ad>] ? CIFSSMBWrite2+0xa3/0x242 [cifs]
> > >>    [<ffffffff8105c342>] ? kthread+0x0/0x85
> > >>    [<ffffffff8100b8e0>] ? kernel_thread_helper+0x0/0x10
> > >>    [<ffffffffa032a117>] ? cifs_writepages+0x461/0x714 [cifs]
> > >> Code: 48 8b 4d d8  [<ffffffff810ac1e8>] ? do_writepages+0x1f/0x28
> > >> 48 8b  [<ffffffff810a4735>] ? __filemap_fdatawrite_range+0x4e/0x50
> > >> 55 e0 48  [<ffffffff810a4c3c>] ? filemap_fdatawrite+0x1a/0x1c
> > >> 8b 75  [<ffffffff810a4c56>] ? filemap_write_and_wait+0x18/0x33
> > >> e8 ff 90  [<ffffffffa0326648>] ? cifs_flush+0x2d/0x60 [cifs]
> > >> a8 00  [<ffffffff810e901f>] ? filp_close+0x3e/0x6d
> > >> 00 00  [<ffffffff810e90f6>] ? sys_close+0xa8/0xe2
> > >> 48 83 c4  [<ffffffff8100aad2>] ? system_call_fastpath+0x16/0x1b
> > >> 28 5b
> > >> ---[ end trace 3387e7bab0a9c645 ]---
> > >
> > > Kaboom. So you're seeing oopses too. Could you get a listing of the
> > > place where it oopsed by following the instructions here?
> > >
> > > http://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Oopses
> > >
> > > I suspect that "sock" is NULL in this case too and it blew up in
> > > kernel_recvmsg.
> > 
> > I added code to WARN_ON when ssocket was null.  This isn't a real panic,
> > just a WARN_ON:
> > 
> > 
> > static int
> > smb_sendv(struct TCP_Server_Info *server, struct kvec *iov, int n_vec)
> > {
> > 	int rc = 0;
> > 	int i = 0;
> > 	struct msghdr smb_msg;
> > 	struct smb_hdr *smb_buffer = iov[0].iov_base;
> > 	unsigned int len = iov[0].iov_len;
> > 	unsigned int total_len;
> > 	int first_vec = 0;
> > 	unsigned int smb_buf_length = smb_buffer->smb_buf_length;
> > 	struct socket *ssocket = server->ssocket;
> > 
> > 	if (ssocket == NULL) {
> > 		cERROR(1, "need to reconnect in sendv here");
> > *** HERE ***	WARN_ON_ONCE(1);
> >   		return -ENOTSOCK; /* BB eventually add reconnect code here */
> > 	}
> > 
> > A second warn-on when ENOTSOCK is perculated up to the calling stack
> > a bit causes the other stack dumpage.  I think the one above is root
> > cause...need to figure out how to have it gracefully bail out and re-connect
> > when it hits this state, as current code just calls this general loop over
> > and over again.
> >
> 
> No, your warning is there, but it's Oopsing too:
> 
> > >> ------------[ cut here ]------------
> > >> WARNING: at /home/greearb/git/linux-2.6.dev.38.y/fs/cifs/transport.c:137 smb_sendv+0x7a/0x2cf [cifs]()
> > >> BUG: unable to handle kernel
> > >> Hardware name: X8ST3
> > >> NULL pointer dereference
> > >> Modules linked in: at 0000000000000020
> > >>    be2iscsi
> > >> IP: iscsi_boot_sysfs [<ffffffff81356230>] __sock_recvmsg_nosec+0x12/0x6e
> 
> 
> ...smb_sendv is called by the "send" side which is generally a
> userspace process. The oops happened on the receive side. cifsd called
> kernel_recvmsg, and it looks like it passed in a NULL sock pointer.
> 

I suspect that the following (untested) patch will fix this. I think
the symptoms that you've seen are consistent with the patch
description. Ben, would you be able to test this in your setup? This
should at least prevent the oopses.

------------------[snip]--------------------

[PATCH] cifs: don't allow cifs_reconnect to exit with NULL socket  pointer

It's possible for the following set of events to happen:

cifsd calls cifs_reconnect which reconnects the socket. A userspace
process then calls cifs_negotiate_protocol to handle the NEGOTIATE and
gets a reply. But, while processing the reply, cifsd calls
cifs_reconnect again.  Eventually the GlobalMid_Lock is dropped and the
reply from the earlier NEGOTIATE completes and the tcpStatus is set to
CifsGood. cifs_reconnect then goes through and closes the socket and sets the
pointer to zero, but because the status is now CifsGood, the new socket
is not created and cifs_reconnect exits with the socket pointer set to
NULL.

Fix this by only setting the tcpStatus to CifsGood if the tcpStatus is
CifsNeedNegotiate, and by making sure that generic_ip_connect is always
called at least once in cifs_reconnect.

Note that this is not a perfect fix for this issue. It's still possible
that the NEGOTIATE reply is handled after the socket has been closed and
reconnected. In that case, the socket state will look correct but it no
NEGOTIATE was performed on it. In that situation though the server
should just shut down the socket on the next attempted send, rather
than causing the oops that occurs today.

Reported-by: Ben Greear <greearb@xxxxxxxxxxxxxxx>
Signed-off-by: Jeff Layton <jlayton@xxxxxxxxxx>
---
 fs/cifs/connect.c |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c
index 84c7307..8bb55bc 100644
--- a/fs/cifs/connect.c
+++ b/fs/cifs/connect.c
@@ -152,7 +152,7 @@ cifs_reconnect(struct TCP_Server_Info *server)
 		mid_entry->callback(mid_entry);
 	}
 
-	while (server->tcpStatus == CifsNeedReconnect) {
+	do {
 		try_to_freeze();
 
 		/* we should try only the port we connected to before */
@@ -167,7 +167,7 @@ cifs_reconnect(struct TCP_Server_Info *server)
 				server->tcpStatus = CifsNeedNegotiate;
 			spin_unlock(&GlobalMid_Lock);
 		}
-	}
+	} while (server->tcpStatus == CifsNeedReconnect);
 
 	return rc;
 }
@@ -3371,7 +3371,7 @@ int cifs_negotiate_protocol(unsigned int xid, struct cifs_ses *ses)
 	}
 	if (rc == 0) {
 		spin_lock(&GlobalMid_Lock);
-		if (server->tcpStatus != CifsExiting)
+		if (server->tcpStatus == CifsNeedNegotiate)
 			server->tcpStatus = CifsGood;
 		else
 			rc = -EHOSTDOWN;
-- 
1.7.5.2


-- 
Jeff Layton <jlayton@xxxxxxxxxx>
--
To unsubscribe from this list: send the line "unsubscribe linux-cifs" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html


[Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux