[linux-cifs] Re: Intermittent issue accessing shares (invalid transact2 word count - (was: 0xc0000034 NT_STATUS_OBJECT_NAME_NOT_FOUND))


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" > 
wrote:

>On Fri, 2 Jan 2015 15:39:32 +0000
>Malte Westerhoff > 
>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 

This message from: http://www.mailbrowse.com/linux-cifs/10393.html
Previous message: Re: [linux-cifs-client] [PATCH] cifs: hard mount option behaviour implementation
Next message:Re: [PATCH] Use memzero_explicit to clear local buffers