Hi Jeff. Thanks for your response and explanation. With wireshark we found that we had mislead ourselves. What we thought was evidence of the issue in the logs was an artefact of our additional instrumentation+monitoring code. As you suggested, in this case the file was indeed simply not there. So let me re-state an actual symptom of the actual issue (now really). When the linux client is experiencing the issue, a simple ls /Storage/WINSERV/ShareName/ (where the share is mounted via autofs in /Storage/WINSERV/ShareName/). Fails with ls: reading directory /Storage/WINSERV/ShareName: Input/output error In the cifsFYI logs we see that it fails with "invalid transact2 word count" 2015-01-05T10:37:44.641407-08:00 winserv kernel: [8326198.517854] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: Getting info on 2015-01-05T10:37:44.641410-08:00 winserv kernel: [8326198.517868] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: For smb_command 50 2015-01-05T10:37:44.641413-08:00 winserv kernel: [8326198.517872] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: Sending smb: smb_len=74 2015-01-05T10:37:44.641425-08:00 winserv kernel: [8326198.518063] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/conne ct.c: RFC1002 header 0x9e 2015-01-05T10:37:44.641427-08:00 winserv kernel: [8326198.518076] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/misc. c: checkSMB Length: 0xa2, smb_buf_length: 0x9e 2015-01-05T10:37:44.642364-08:00 winserv kernel: [8326198.518099] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: cifs_sync_mid_result: cmd=50 mid=55064 state=4 2015-01-05T10:37:44.642385-08:00 winserv kernel: [8326198.518111] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: cifs_revalidate_cache: revalidating inode 281474976711418 2015-01-05T10:37:44.642389-08:00 winserv kernel: [8326198.518114] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: cifs_revalidate_cache: invalidating inode 281474976711418 mapping 2015-01-05T10:37:44.642392-08:00 winserv kernel: [8326198.518119] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 65647593) rc = 0 2015-01-05T10:37:44.642395-08:00 winserv kernel: [8326198.518169] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: CIFS VFS: in cifs_readdir as Xid: 65647594 with uid: 0 2015-01-05T10:37:44.642397-08:00 winserv kernel: [8326198.518175] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: Full path: start at: 0 2015-01-05T10:37:44.642431-08:00 winserv kernel: [8326198.518178] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/cifss mb.c: In FindFirst for 2015-01-05T10:37:44.642434-08:00 winserv kernel: [8326198.518184] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: For smb_command 50 2015-01-05T10:37:44.642436-08:00 winserv kernel: [8326198.518187] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: Sending smb: smb_len=84 2015-01-05T10:37:44.642438-08:00 winserv kernel: [8326198.518435] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/conne ct.c: RFC1002 header 0x23 2015-01-05T10:37:44.642440-08:00 winserv kernel: [8326198.518447] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/misc. c: checkSMB Length: 0x27, smb_buf_length: 0x23 2015-01-05T10:37:44.642442-08:00 winserv kernel: [8326198.518455] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/smb1o ps.c: invalid transact2 word count 2015-01-05T10:37:44.642444-08:00 winserv kernel: [8326198.518505] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: cifs_sync_mid_result: cmd=50 mid=55065 state=4 2015-01-05T10:37:44.642445-08:00 winserv kernel: [8326198.518517] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/netmi sc.c: Mapping smb error code 0x710001 to POSIX err -5 2015-01-05T10:37:44.642446-08:00 winserv kernel: [8326198.518523] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/cifss mb.c: Error in FindFirst = -5 2015-01-05T10:37:44.642449-08:00 winserv kernel: [8326198.518527] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: initiate cifs search rc -5 2015-01-05T10:37:44.642450-08:00 winserv kernel: [8326198.518530] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: CIFS VFS: leaving cifs_readdir (xid = 65647594) rc = -5 2015-01-05T10:37:44.642451-08:00 winserv kernel: [8326198.518627] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/file. c: Closedir inode = 0xffff880939306d00 2015-01-05T10:37:44.642452-08:00 winserv kernel: [8326198.518632] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/file. c: CIFS VFS: in cifs_closedir as Xid: 65647595 with uid: 0 2015-01-05T10:37:44.642455-08:00 winserv kernel: [8326198.518634] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/file. c: Freeing private data in close dir 2015-01-05T10:37:44.642456-08:00 winserv kernel: [8326198.518637] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/file. c: CIFS VFS: leaving cifs_closedir (xid = 65647595) rc = 0 Once the share is in that state, any subsequent ls fail. Unmounting and re-mounting the share fixes the issue. For comparison, the respective lines for the same ls when the server is in good condition look like this (response length much more reasonable): 2015-01-05T10:39:44.580427-08:00 winserv kernel: [8326318.541673] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: cifs_revalidate_cache: revalidating inode 281474976711418 2015-01-05T10:39:44.580428-08:00 winserv kernel: [8326318.541676] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: cifs_revalidate_cache: invalidating inode 281474976711418 mapping 2015-01-05T10:39:44.580429-08:00 winserv kernel: [8326318.541681] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/inode .c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 65650225) rc = 0 2015-01-05T10:39:44.580431-08:00 winserv kernel: [8326318.541724] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: CIFS VFS: in cifs_readdir as Xid: 65650226 with uid: 0 2015-01-05T10:39:44.580433-08:00 winserv kernel: [8326318.541729] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: Full path: start at: 0 2015-01-05T10:39:44.580434-08:00 winserv kernel: [8326318.541732] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/cifss mb.c: In FindFirst for 2015-01-05T10:39:44.580436-08:00 winserv kernel: [8326318.541737] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: For smb_command 50 2015-01-05T10:39:44.580438-08:00 winserv kernel: [8326318.541740] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: Sending smb: smb_len=84 2015-01-05T10:39:44.580439-08:00 winserv kernel: [8326318.541950] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/conne ct.c: RFC1002 header 0x6dc 2015-01-05T10:39:44.580440-08:00 winserv kernel: [8326318.541964] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/misc. c: checkSMB Length: 0x6e0, smb_buf_length: 0x6dc 2015-01-05T10:39:44.580441-08:00 winserv kernel: [8326318.541981] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/trans port.c: cifs_sync_mid_result: cmd=50 mid=62728 state=4 2015-01-05T10:39:44.580465-08:00 winserv kernel: [8326318.541990] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: initiate cifs search rc 0 2015-01-05T10:39:44.580467-08:00 winserv kernel: [8326318.541993] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: found entry - pos_in_buf 0 2015-01-05T10:39:44.580468-08:00 winserv kernel: [8326318.541996] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: entry 2 found 2015-01-05T10:39:44.580470-08:00 winserv kernel: [8326318.542002] /home/abuild/rpmbuild/BUILD/kernel-desktop-3.11.10/linux-3.11/fs/cifs/readd ir.c: loop through 19 times filling dir for net buf ffff883e7ee We have been able to capture such a failed ls with wireshark (even though the capture only started when the server was already in the bad state): 405 2015-01-05 14:09:36.609638 172.16.107.133 172.16.107.135 SMB 154 Trans2 Request, FIND_FIRST2, Pattern: \* 406 2015-01-05 14:09:36.609789 172.16.107.135 172.16.107.133 SMB 105 Trans2 Response, FIND_FIRST2, Error: Unknown DOS error (71) (Packet details attached) Obviously this would point to the Windows Server being in a bad state. However would the issue then be fixed with re-mounting the share on the linux side. The symptoms look somewhat similar to: http://comments.gmane.org/gmane.linux.file-systems.cifs/5438 Do you believe that the noserverino option could help here? Thanks Malte On 02/01/15 22:45, "Jeff Layton" <jlayton@ <mailto:jlayton@xxxxxxxxx>> wrote: >On Fri, 2 Jan 2015 15:39:32 +0000 >Malte Westerhoff <MWesterhoff@ <mailto:MWesterhoff@xxxxxxxxxxxxxxxxx>> >wrote: > >>... >Can you ascertain whether the file is _actually_ present at the time >that this occurs? Could another client is competing with this one to ... >remove files? Perhaps the server is just insane and is returning that >error when the file really exists? Maybe the client is sending bad >filenames for some reason? > >There are tons of possibilities. You'll probably need to do some >investigative work to determine the root cause. > >> > >-- >Jeff Layton <jlayton@xxxxxxxxx>
Attachment:
default.png
Description: default.png
