Re: hung system with cifsd, cannot reduce timeout

[Patrick Noffke <patrick-0qqNeQ6W4hOzQB+pC5nmwQ@public.gmane.org>]

[-- Attachment #1: Type: text/plain, Size: 2542 bytes --]

On Thursday, December 05, 2013 03:36:11 PM you wrote:
> On 12/05/2013 03:03 PM, Patrick Noffke wrote:
> > Hi,
> > 
> > I did check the cifsd stack (cat /proc/<cifsd PID>/stack) for previous
> > tests, and it was waiting on a recv, and its state was SW (not DW).
> > Unfortunately, I did not get the stack for this test.
> 
> I just repeated this test, and this time cifsd was in the SW state.
> 
> The stack was as follows:
> sk_wait_data
> tcp_recvmsg
> inet_recvmsg
> sock_recvmsg
> kernel_recvmsg
> cifs_readv_from_socket
> cifs_read_from_socket
> cifs_readv_discard
> cifs_readv_receive
> cifs_demultiplex_thread
> kthread
> ret_from_fork
> 
> For this test, my process and ps were hung after the first time pulling
> the cable (I hadn't rebooted from my earlier test, but I think the CIFS
> connection had disconnected due to inactivity).
> 
> As before, an Echo Request was sent on a previous connection after
> sending the SYN and Negotiate on a new connection.  The server RST the
> old connection right after the Echo Request, and 115 seconds later RST
> the new connection.  Another new connection was then made, and the
> process resumed and ps completed.
> 

I have a little more info from yet another test with the same symptoms.  I 
did:

echo 1 > /proc/fs/cifs/cifsFYI

and ran the test again.  I had klogd running, so the cifs debug logs went to 
the syslog.  I've attached the syslogs around the time when I pulled the 
cable, reattached it, and up until the system recovers.

A few notes about these logs:

22:29:18:  Ethernet cable is disconnected.
22:29:22:  Echo request is sent
22:29:27:  Second echo request is sent
22:29:31:  Reconnect due to no echo response.  Socket is created at this time.
22:29:31:  (Last log for this timestamp) Ethernet cable is reconnected.  I 
believe the echo request must have been queued up for sending, which is why I 
see it in wireshark after reconnecting the cable (even though the echo 
requests were logged prior to the reconnection).  Server also sends RST for 
first connection at this time.
22:29:57:  Last cifs log until server sends RST.  Last message is 
"fs/cifs/inode.c: Getting info on"
22:32:09:  Server sends RST on second connection, client reconnects, and the 
system recovers.

It seems like the "Getting info on" log message is missing a filename.  Would 
this explain why it's hung until the server sends a RST?

There are also logs like the following before the cable is reattached:
fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release

Best regards,
Patrick

[-- Attachment #2: cifs-lockup-syslogs.gz --]
[-- Type: application/gzip, Size: 3467 bytes --]