Opened 5 years ago

Closed 4 years ago

#263 closed defect (fixed)

Connection timeout (sleep with slow awakening)

Reported by: Lewis Rosenthal Owned by:
Priority: minor Milestone:
Component: Samba Client Plugin Version: Client 3.0.x
Keywords: sleep, connection, wake, reconnect Cc: Paul Smedley

Description

This continues the discussion we've had on the dev list, as it just happened to me with a NTLM/SMB1 share.

Connection was mapped and working. It sat idle for 61 minutes and few seconds. using 4OS2, I attempted a tab completion for a path, and got a beep (as it might if the drive were disconnected or the beginning of the path otherwise invalid).

Using ndpsmb-samba_4.2.3-heimdal-20150716b, log.ndpsmb shows:

2015/07/28 14:16:39.58: 9 2: NdpRsrcQueryInfo in
2015/07/28 14:16:39.62: 9 2: NdpRsrcQueryInfo 0
2015/07/28 14:16:39.62: 9 2: NdpRsrcQueryInfo in
2015/07/28 14:16:39.62: 9 2: NdpRsrcQueryInfo 0
2015/07/28 14:16:39.62: 9 2: NdpQueryPathInfo in [0x6213c0] <im*>
2015/07/28 14:16:39.63: 9 2: NdpFindStart in [0x6213c0]
2015/07/28 14:16:39.63: 9 2: NdpFindStart: dir [\], dir_mask [im*], mask [\*], szPath [im*]
2015/07/28 14:16:39.63: 4 2:  smbwrp_filelist
2015/07/28 14:16:39.63: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2015/07/28 14:16:39.63: 1 2: list_files
2015/07/28 14:16:39.63: 9 2: dircache_list_files []
2015/07/28 14:16:39.63: 9 2: findDirCache: []
2015/07/28 14:16:39.63: 9 2: findDirCache: entry [LOTUS\Cantiag\ARCHIVE.FWK\COMMERCE.WK1]
2015/07/28 14:16:39.63: 9 2: findDirCache: entry [LOTUS\Cantiag\ARCHIVE.FWK]
2015/07/28 14:16:39.63: 9 2: findDirCache: entry [LOTUS\Cantiag]
2015/07/28 14:16:39.63: 9 2: findDirCache: entry [LOTUS]
2015/07/28 14:16:39.64: 9 2: findDirCache: entry []
2015/07/28 14:16:39.64: 9 2: dcePathEqualTo: [] []
2015/07/28 14:16:39.64: 9 2: findDirCache: 0x66f9e0
2015/07/28 14:16:39.64: 9 2: CacheRead: entry 0x66f9e0 found for []
2015/07/28 14:16:39.64: 9 2: CacheRead: expired
2015/07/28 14:16:39.64: 9 2: CacheRead: [], 0
2015/07/28 14:16:39.64: 4 2: list_files level 260. mask <\*>
2015/07/28 14:16:39.67: 9 2: NdpFindStart <im*> (\im*) cnt 0 0
2015/07/28 14:16:40.62: 9 2: NdpRsrcQueryInfo in
2015/07/28 14:16:40.62: 9 2: NdpRsrcQueryInfo 0
2015/07/28 14:16:40.62: 9 2: NdpRsrcQueryInfo in
2015/07/28 14:16:40.62: 9 2: NdpRsrcQueryInfo 0

A subsequent:

dir g:\

paused for a few seconds, then provided results. Afterward, the same tab completion as above worked as expected (no delay; no beep).

Obviously, using CMD this would not be an issue, as there is no tab completion. I suspect that if we were able to cache the dir entries, this might also not be an issue, as we would return results from cache first (though an hour would be a long cache timeout).

Note that EA support is enabled for this share, even though the server does not support EAs over CIFS. I doubt that this has any bearing, however (the log does correctly report failure to get EA data when listing files).

Change History (24)

comment:1 Changed 5 years ago by Lewis Rosenthal

This remains an issue with ndpsmb-samba_4.3.0rc3-heimdal-20150820. Once the cache expires, directories are not re-cached, tab completion fails, as does dir (tested against SMB1 share, with NTLM auth). Log snippet (dir <NetDrive? volume>:) from log.ndpsmb:

2015/08/21 10:55:34.93: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.0: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.0: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.0: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.0: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.0: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.1: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2015/08/21 10:55:35.1: 9 2: checkMountResource in tid#2
2015/08/21 10:55:35.1: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2015/08/21 10:55:35.1: 1 2: NTLMv1 Support enabled
2015/08/21 10:55:35.28: 4 2: Server supports NT1 protocol
2015/08/21 10:55:35.28: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2015/08/21 10:55:35.36: 4 2: logon by Lewis succeeded
2015/08/21 10:55:35.36: 4 2:  session setup ok. Sending tconx <data> <********>
2015/08/21 10:55:35.40: 4 2:  tconx ok
2015/08/21 10:55:35.40: 4 2:  smbwrp_dskattr
2015/08/21 10:55:35.43: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2015/08/21 10:55:35.43: 9 2: smbwrp_disconnect3
2015/08/21 10:55:35.43: 4 2:  smbwrp_disconnect
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo in
2015/08/21 10:55:35.46: 9 2: NdpRsrcQueryInfo 0
2015/08/21 10:55:35.46: 9 2: NdpQueryPathInfo in [0x627300] <*>
2015/08/21 10:55:35.47: 9 2: NdpFindStart in [0x627300]
2015/08/21 10:55:35.47: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2015/08/21 10:55:35.47: 4 2:  smbwrp_filelist
2015/08/21 10:55:35.47: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2015/08/21 10:55:35.47: 1 2: list_files
2015/08/21 10:55:35.47: 9 2: dircache_list_files []
2015/08/21 10:55:35.47: 9 2: findDirCache: []
2015/08/21 10:55:35.47: 9 2: findDirCache: entry [hca3\data]
2015/08/21 10:55:35.47: 9 2: findDirCache: entry [hca3\HISTORY]
2015/08/21 10:55:35.47: 9 2: findDirCache: entry [hca3]
2015/08/21 10:55:35.47: 9 2: findDirCache: 0
2015/08/21 10:55:35.47: 9 2: CacheRead: [], 0
2015/08/21 10:55:35.47: 4 2: list_files level 260. mask <\*>
2015/08/21 10:55:35.48: 9 2: NdpFindStart <*> (\*) cnt 0 0

Stopping the control program and starting it, gets this working again.

Note also reference to:

Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE

Not sure if this is extra noise or something of importance.

comment:2 Changed 4 years ago by Lewis Rosenthal

Condition still present with ndpsmb-samba_4.4.0rc3-heimdal-20160229.zip. After sitting idle between 13:35:30 and 23:38:21, attempting dir on an NTLMv1 share gets me a beep and the following in the log:

2016/03/18 23:38:21.75: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:21.79: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/03/18 23:38:21.79: 9 2: checkMountResource in tid#2
2016/03/18 23:38:21.79: 1 2: Connecting to \\lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/03/18 23:38:21.79: 1 2: NTLMv1 Support enabled
2016/03/18 23:38:22.43: 4 2: Server supports NT1 protocol
2016/03/18 23:38:22.43: 4 2:  session setuping for <lewis>/<********> in <workgroup>
2016/03/18 23:38:22.56: 4 2: logon by lewis succeeded
2016/03/18 23:38:22.56: 4 2:  session setup ok. Sending tconx <data> <********>
2016/03/18 23:38:22.60: 4 2:  tconx ok
2016/03/18 23:38:22.60: 4 2:  smbwrp_dskattr
2016/03/18 23:38:22.65: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/03/18 23:38:22.65: 4 2:  smbwrp_disconnect
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo in
2016/03/18 23:38:22.69: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@lewis
2016/03/18 23:38:22.69: 9 2: NdpQueryPathInfo in [0x670940] <*>
2016/03/18 23:38:22.69: 9 2: NdpFindStart in [0x670940]
2016/03/18 23:38:22.69: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/03/18 23:38:22.69: 4 2:  smbwrp_filelist
2016/03/18 23:38:22.70: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/03/18 23:38:22.70: 1 2: list_files
2016/03/18 23:38:22.70: 9 2: dircache_list_files []
2016/03/18 23:38:22.70: 9 2: findDirCache: []
2016/03/18 23:38:22.70: 9 2: findDirCache: entry [Images\NY\Billing\Clients\ColPal]
2016/03/18 23:38:22.70: 9 2: findDirCache: entry [Images\NY\Billing\Clients]
2016/03/18 23:38:22.70: 9 2: findDirCache: entry [Images\NY\Billing]
2016/03/18 23:38:22.70: 9 2: findDirCache: entry [Images\NY]
2016/03/18 23:38:22.70: 9 2: findDirCache: entry [Images]
2016/03/18 23:38:22.70: 9 2: findDirCache: entry []
2016/03/18 23:38:22.70: 9 2: dcePathEqualTo: [] []
2016/03/18 23:38:22.70: 9 2: findDirCache: 0x6732a0
2016/03/18 23:38:22.70: 9 2: CacheRead: entry 0x6732a0 found for []
2016/03/18 23:38:22.70: 9 2: CacheRead: expired
2016/03/18 23:38:22.70: 9 2: CacheRead: [], 0
2016/03/18 23:38:22.70: 4 2: list_files level 260. mask <\*>
2016/03/18 23:38:22.70: 9 2: NdpFindStart <*> (\*) cnt 0 0

FTP plugin continues to work as expected. The only way to regain access to Samba share is to restart the control program.

comment:3 Changed 4 years ago by Lewis Rosenthal

Quick update, here.

What I've discovered is that the lag must be between accesses of the/a Samba share and not from the time the control program is started. Thus, I can boot the system, let it sit idle overnight, and the next day, my first access of a Samba share will proceed as expected. However, if I boot, access the share, and then leave it idle, the next access will fail.

comment:4 Changed 4 years ago by Paul Smedley

Hmm I wonder if it is related to caching? It might be interesting to back out the caching code and see if the problem goes away. That would give some good clues...

comment:5 Changed 4 years ago by Paul Smedley

Default cache time is only 10 seconds, so I struggle to see any relationship there... I'll try and see if I can reproduce here. I've just accessed my samba server and will try again in an hour....

comment:6 Changed 4 years ago by Paul Smedley

No delay here after the client idling for an hour..... I did a dir though, not an attempt at filename completion. I will try the tab filename completion again in another hour

comment:7 Changed 4 years ago by Paul Smedley

All good with tab completion here after an hour as well....

Any other tips on trying to reproduce? Server here is running Samba 4.3.x on Ubuntu Server 16.04

comment:8 Changed 4 years ago by Lewis Rosenthal

What authentication are you using, Paul? I have a hunch that we won't see this with Kerberos, only with NTLMv1/v2.

Using your latest 4.4.2, I started the control program and ran a dir against an NTLMv1-authenticated SMB1 share. I let the system sit overnight, and I had no connectivity (dir failed) this morning until I stopped and restarted the control program.

comment:9 Changed 4 years ago by Paul Smedley

I must work out how to subscribe to bug reports so that I see when updates are posted. I'm using SMB3 - not sure about authentication method, whatever Samba 4.x defaults to I suspect. Not kerberos.

comment:10 Changed 4 years ago by Paul Smedley

Cc: Paul Smedley added

comment:11 Changed 4 years ago by Paul Smedley

I just did some testing to a Samba Server running eCS, connection protocol is NT1. I also don't see the hang there. Anything unusual in smb.conf that could be contributing?

Can you upload a full log.ndpsmb?

Last edited 4 years ago by Paul Smedley (previous) (diff)

comment:12 Changed 4 years ago by Lewis Rosenthal

Hmmm...

I thought of this the other day, and meant to have another look. Possible side-effect of spnego?

[global]
        workgroup = WORKGROUP
        loglevel = 10
        client ntlmv2 auth = no
        client use spnego = yes

That was a leftover from when we first started testing Kerberos. I'll turn it off. What does yours say?

comment:13 Changed 4 years ago by Lewis Rosenthal

Resolution: invalid
Status: newclosed

Closing this as invalid.

Changing client use spnego = no seems to have resolved the issue. We might consider whether a change is needed to the default behavior or whether this should be a readme item when using non-SPNEGO methods.

Sorry to have wasted your time with this, Paul. Thanks for testing and providing a comparison. I should have re-tested on a clean system.

comment:14 Changed 4 years ago by Lewis Rosenthal

Resolution: invalid
Status: closedreopened

Ah, wait...

I was wrong.

After sitting overnight:

[c:\]dir g:

fails, while:

[c:\]dir g:\Temp

succeeds.

comment:15 Changed 4 years ago by Paul Smedley

logs or it didn't happen :)

comment:16 Changed 4 years ago by Lewis Rosenthal

Well, I was going to point to #261, but realized that I hadn't posted the log there, so...

2016/04/28 08:48:02.23: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.23: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.24: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.24: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.24: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.24: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.24: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/04/28 08:48:02.24: 9 2: checkMountResource in tid#2
2016/04/28 08:48:02.24: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/04/28 08:48:02.24: 1 2: NTLMv1 Support enabled
2016/04/28 08:48:02.45: 4 2: Server supports NT1 protocol
2016/04/28 08:48:02.45: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/04/28 08:48:02.52: 4 2: logon by Lewis succeeded
2016/04/28 08:48:02.52: 4 2:  session setup ok. Sending tconx <data> <********>
2016/04/28 08:48:02.55: 4 2:  tconx ok
2016/04/28 08:48:02.55: 4 2:  smbwrp_dskattr
2016/04/28 08:48:02.59: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/28 08:48:02.59: 4 2:  smbwrp_disconnect
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.62: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.63: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.63: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:02.63: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:02.63: 9 2: NdpQueryPathInfo in [0x6709c0] <*>
2016/04/28 08:48:02.63: 9 2: NdpFindStart in [0x6709c0]
2016/04/28 08:48:02.63: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/04/28 08:48:02.63: 4 2:  smbwrp_filelist
2016/04/28 08:48:02.63: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/04/28 08:48:02.63: 1 2: list_files
2016/04/28 08:48:02.63: 9 2: dircache_list_files []
2016/04/28 08:48:02.63: 9 2: findDirCache: []
2016/04/28 08:48:02.63: 9 2: findDirCache: 0
2016/04/28 08:48:02.63: 9 2: CacheRead: [], 0
2016/04/28 08:48:02.63: 4 2: list_files level 260. mask <\*>
2016/04/28 08:48:02.63: 9 2: NdpFindStart <*> (\*) cnt 0 0
2016/04/28 08:48:08.85: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:08.85: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:08.85: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:08.85: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:08.86: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:08.86: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:08.86: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/04/28 08:48:08.86: 9 2: checkMountResource in tid#2
2016/04/28 08:48:08.86: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/04/28 08:48:08.86: 1 2: NTLMv1 Support enabled
2016/04/28 08:48:09.20: 4 2: Server supports NT1 protocol
2016/04/28 08:48:09.20: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/04/28 08:48:09.28: 4 2: logon by Lewis succeeded
2016/04/28 08:48:09.28: 4 2:  session setup ok. Sending tconx <data> <********>
2016/04/28 08:48:09.31: 4 2:  tconx ok
2016/04/28 08:48:09.31: 4 2:  smbwrp_dskattr
2016/04/28 08:48:09.35: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/28 08:48:09.35: 4 2:  smbwrp_disconnect
2016/04/28 08:48:09.38: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:09.39: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:09.39: 9 2: NdpQueryPathInfo in [0x6709c0] <temp>
2016/04/28 08:48:09.39: 9 2: dircache_find_path [temp]
2016/04/28 08:48:09.39: 9 2: dcFindPath: [][temp]
2016/04/28 08:48:09.39: 9 2: dircache: FindPath temp not found
2016/04/28 08:48:09.39: 9 2: NdpQueryPathInfo pathparser for <\temp> rc=0
2016/04/28 08:48:09.39: 9 2: NdpQueryPathInfo smbwrp_getattr for <\temp>
2016/04/28 08:48:09.39: 4 2:  smbwrp_echo
2016/04/28 08:48:09.40: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/04/28 08:48:09.40: 1 2: NTLMv1 Support enabled
2016/04/28 08:48:09.59: 4 2: Server supports NT1 protocol
2016/04/28 08:48:09.59: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/04/28 08:48:09.65: 4 2: logon by Lewis succeeded
2016/04/28 08:48:09.65: 4 2:  session setup ok. Sending tconx <data> <********>
2016/04/28 08:48:09.69: 4 2:  tconx ok
2016/04/28 08:48:09.69: 4 2:  smbwrp_getattr
2016/04/28 08:48:09.69: 4 2: getattr 0 16 <\temp>
2016/04/28 08:48:09.69: 4 2: smbwrp_getattr, calling cli_qpathinfo2
2016/04/28 08:48:09.72: 9 2: fname \temp
2016/04/28 08:48:09.72: 9 2: size 0
2016/04/28 08:48:09.72: 9 2: mtime 1461251385 Thu Apr 21 11:09:45 2016
2016/04/28 08:48:09.72: 9 2: ftimeLastAccess 11:09:44
2016/04/28 08:48:09.73: 9 2: NdpQueryPathInfo <temp> (\temp) 0
2016/04/28 08:48:09.73: 9 2: NdpEASize in [0x6709c0] <\temp> 
2016/04/28 08:48:09.73: 4 2:  smbwrp_listea
2016/04/28 08:48:09.73: 4 2: EAList for <\temp>
2016/04/28 08:48:09.76: 4 2: ea_get_file list failed - NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/28 08:48:09.76: 9 2: NdpEASize <temp> 0 282
2016/04/28 08:48:09.77: 9 2: NdpRsrcQueryInfo in
2016/04/28 08:48:09.77: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/28 08:48:09.77: 9 2: NdpQueryPathInfo in [0x6709c0] <temp\*>
2016/04/28 08:48:09.77: 9 2: NdpFindStart in [0x6709c0]
2016/04/28 08:48:09.77: 9 2: NdpFindStart: dir [\temp\], dir_mask [*], mask [\temp\*], szPath [temp\*]
2016/04/28 08:48:09.77: 4 2:  smbwrp_filelist
2016/04/28 08:48:09.77: 1 2: Filelist <\temp\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/04/28 08:48:09.77: 1 2: list_files
2016/04/28 08:48:09.77: 9 2: dircache_list_files [temp]
2016/04/28 08:48:09.77: 9 2: findDirCache: [temp]
2016/04/28 08:48:09.77: 9 2: findDirCache: 0
2016/04/28 08:48:09.77: 9 2: CacheRead: [temp], 0
2016/04/28 08:48:09.77: 4 2: list_files level 260. mask <\temp\*>

This is essentially as I posted it, above, I think. There is one other possibility we haven't discussed: NetWare?'s CIFS implementation, unlike the native NW.IFS, does not support EAs, yet I have EA support enabled for the share. Thus, I do see repeated entries in the log for:

2016/04/27 23:32:29.44: 9 2: NdpEASize in [0x6709c0] <\HCA5>
2016/04/27 23:32:29.44: 4 2:  smbwrp_listea
2016/04/27 23:32:29.44: 4 2: EAList for <\HCA5>
2016/04/27 23:32:29.47: 4 2: ea_get_file list failed - NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/27 23:32:29.47: 9 2: NdpEASize <HCA5> 0 282

I wonder if the lack of EA support has any bearing on this (when the client is configured to expect it)? I'll try specifically disabling EA support.

comment:17 Changed 4 years ago by Lewis Rosenthal

Fresh attempt (before I had to go sifting):

2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.11: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.12: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/04/29 01:15:07.12: 9 2: checkMountResource in tid#2
2016/04/29 01:15:07.12: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/04/29 01:15:07.12: 1 2: NTLMv1 Support enabled
2016/04/29 01:15:07.45: 4 2: Server supports NT1 protocol
2016/04/29 01:15:07.45: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/04/29 01:15:07.55: 4 2: logon by Lewis succeeded
2016/04/29 01:15:07.56: 4 2:  session setup ok. Sending tconx <data> <********>
2016/04/29 01:15:07.59: 4 2:  tconx ok
2016/04/29 01:15:07.59: 4 2:  smbwrp_dskattr
2016/04/29 01:15:07.62: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/29 01:15:07.63: 4 2:  smbwrp_disconnect
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.66: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:15:07.67: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:15:07.67: 9 2: NdpQueryPathInfo in [0x689a20] <*>
2016/04/29 01:15:07.67: 9 2: NdpFindStart in [0x689a20]
2016/04/29 01:15:07.67: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/04/29 01:15:07.67: 4 2:  smbwrp_filelist
2016/04/29 01:15:07.67: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/04/29 01:15:07.67: 1 2: list_files
2016/04/29 01:15:07.67: 9 2: dircache_list_files []
2016/04/29 01:15:07.67: 9 2: findDirCache: []
2016/04/29 01:15:07.67: 9 2: findDirCache: entry []
2016/04/29 01:15:07.67: 9 2: dcePathEqualTo: [] []
2016/04/29 01:15:07.67: 9 2: findDirCache: 0x6765c0
2016/04/29 01:15:07.67: 9 2: CacheRead: entry 0x6765c0 found for []
2016/04/29 01:15:07.67: 9 2: CacheRead: expired
2016/04/29 01:15:07.67: 9 2: CacheRead: [], 0
2016/04/29 01:15:07.67: 4 2: list_files level 260. mask <\*>
2016/04/29 01:15:07.67: 9 2: NdpFindStart <*> (\*) cnt 0 0

Result:

SYS0002: The system cannot find the file specified.

Once I tack on a directory ("\" by itself won't do; it must be a directory name), I then get:

2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryFSAllocate 87/0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:18:35.43: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:18:35.43: 9 2: NdpQueryPathInfo in [0x689a20] <temp>
2016/04/29 01:18:35.43: 9 2: dircache_find_path [temp]
2016/04/29 01:18:35.43: 9 2: dcFindPath: [][temp]
2016/04/29 01:18:35.43: 9 2: dircache: FindPath temp not found
2016/04/29 01:18:35.43: 9 2: NdpQueryPathInfo pathparser for <\temp> rc=0
2016/04/29 01:18:35.43: 9 2: NdpQueryPathInfo smbwrp_getattr for <\temp>
2016/04/29 01:18:35.43: 4 2:  smbwrp_echo
2016/04/29 01:18:35.45: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/04/29 01:18:35.45: 1 2: NTLMv1 Support enabled
2016/04/29 01:18:35.67: 4 2: Server supports NT1 protocol
2016/04/29 01:18:35.67: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/04/29 01:18:35.74: 4 2: logon by Lewis succeeded
2016/04/29 01:18:35.74: 4 2:  session setup ok. Sending tconx <data> <********>
2016/04/29 01:18:35.78: 4 2:  tconx ok
2016/04/29 01:18:35.78: 4 2:  smbwrp_getattr
2016/04/29 01:18:35.78: 4 2: getattr 0 16 <\temp>
2016/04/29 01:18:35.78: 4 2: smbwrp_getattr, calling cli_qpathinfo2
2016/04/29 01:18:35.81: 9 2: fname \temp
2016/04/29 01:18:35.81: 9 2: size 0
2016/04/29 01:18:35.82: 9 2: mtime 1461251385 Thu Apr 21 11:09:45 2016
2016/04/29 01:18:35.82: 9 2: ftimeLastAccess 11:09:44
2016/04/29 01:18:35.82: 9 2: NdpQueryPathInfo <temp> (\temp) 0
2016/04/29 01:18:35.82: 9 2: NdpEASize in [0x689a20] <\temp> 
2016/04/29 01:18:35.82: 4 2:  smbwrp_listea
2016/04/29 01:18:35.82: 4 2: EAList for <\temp>
2016/04/29 01:18:35.85: 4 2: ea_get_file list failed - NT_STATUS_INVALID_NETWORK_RESPONSE
2016/04/29 01:18:35.85: 9 2: NdpEASize <temp> 0 282
2016/04/29 01:18:35.85: 9 2: NdpRsrcQueryInfo in
2016/04/29 01:18:35.85: 9 2: NdpRsrcQueryInfo 0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/04/29 01:18:35.85: 9 2: NdpQueryPathInfo in [0x689a20] <temp\*>
2016/04/29 01:18:35.85: 9 2: NdpFindStart in [0x689a20]
2016/04/29 01:18:35.85: 9 2: NdpFindStart: dir [\temp\], dir_mask [*], mask [\temp\*], szPath [temp\*]
2016/04/29 01:18:35.86: 4 2:  smbwrp_filelist
2016/04/29 01:18:35.86: 1 2: Filelist <\temp\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/04/29 01:18:35.86: 1 2: list_files
2016/04/29 01:18:35.86: 9 2: dircache_list_files [temp]
2016/04/29 01:18:35.86: 9 2: findDirCache: [temp]
2016/04/29 01:18:35.86: 9 2: findDirCache: 0
2016/04/29 01:18:35.86: 9 2: CacheRead: [temp], 0
2016/04/29 01:18:35.86: 4 2: list_files level 260. mask <\temp\*>
2016/04/29 01:18:36.85: 9 2: dircache_write_begin pdc 0x625800 path [temp]
2016/04/29 01:18:36.85: 9 2: findDirCache: [temp]
2016/04/29 01:18:36.86: 9 2: findDirCache: 0
2016/04/29 01:18:36.86: 9 2: CacheWriteBegin: temp
2016/04/29 01:18:36.86: 9 2: dircache_write_begin returning ctx 0x679b60
2016/04/29 01:18:36.86: 4 2: list_files: got 54 files
2016/04/29 01:18:36.86: 4 2:  smbwrp_dir_add
2016/04/29 01:18:36.86: 8 2: adding <.> 289 0 261
2016/04/29 01:18:36.86: 9 2: fname \temp\.
2016/04/29 01:18:36.86: 9 2: size 0
2016/04/29 01:18:36.86: 9 2: mtime 1461251385 Thu Apr 21 11:09:45 2016
2016/04/29 01:18:36.86: 9 2: ftimeLastAccess 11:09:44
2016/04/29 01:18:36.86: 9 2: dircache_write_entry 0x679b60
2016/04/29 01:18:36.86: 4 2:  smbwrp_dir_add
2016/04/29 01:18:36.86: 8 2: adding <..> 289 0 261
2016/04/29 01:18:36.86: 9 2: fname \temp\..
2016/04/29 01:18:36.86: 9 2: size 0
2016/04/29 01:18:36.86: 9 2: mtime 1461010663 Mon Apr 18 16:17:43 2016
2016/04/29 01:18:36.86: 9 2: ftimeLastAccess 16:17:42
2016/04/29 01:18:36.86: 9 2: dircache_write_entry 0x679b60
2016/04/29 01:18:36.86: 4 2:  smbwrp_dir_add

and the listing proceeds as expected.

comment:18 Changed 4 years ago by Paul Smedley

Can you please try (with latest 4.4.4 code): [c:\]dir g:

wait 1 hour 1 minute (or however long you normally wait) then: [c:\]dir g: (again)

and send unedited ndpsmb.log?

I'd like to see a log for a working and non-working case of the same directory listing.

I really wish I could reproduce locally :(

comment:19 Changed 4 years ago by Lewis Rosenthal

Aha...

Got the condition with SMB1. Did not get it with SMB3_11.

Sending unedited logs privately, as there is some directory content which may not be suitable for public display.

I should try toggling EA support for the NetWare CIFS off, just in case that's a factor.

comment:20 Changed 4 years ago by Lewis Rosenthal

I should try toggling EA support for the NetWare CIFS off, just in case that's a factor.

I can confirm that whether EAs are enabled for the non-EA-aware SMB1 share, this condition is consistent.

comment:21 Changed 4 years ago by Lewis Rosenthal

Seems fixed with:

6-22-16 3:51 13,953,656 124 ndpsmb.dll

First run ([c:\]dir g:):

2016/06/22 16:37:29.8: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:29.12: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:29.12: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:29.12: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:29.14: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:29.14: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:29.14: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/06/22 16:37:29.14: 9 2: checkMountResource in tid#2
2016/06/22 16:37:29.16: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/22 16:37:29.17: 1 2: NTLMv1 Support enabled
2016/06/22 16:37:29.78: 4 2: Server supports NT1 protocol
2016/06/22 16:37:29.78: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/22 16:37:30.15: 4 2: logon by Lewis succeeded
2016/06/22 16:37:30.15: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/22 16:37:30.19: 4 2:  tconx ok
2016/06/22 16:37:30.19: 4 2:  smbwrp_dskattr
2016/06/22 16:37:30.27: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/06/22 16:37:30.27: 4 2:  smbwrp_disconnect
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryFSAllocate rc=87/rc1=0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 16:37:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 16:37:30.40: 9 2: NdpCreateConnection in
2016/06/22 16:37:30.40: 9 2: NdpCreateConnection send CONNECT
2016/06/22 16:37:30.40: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/22 16:37:30.40: 1 2: NTLMv1 Support enabled
2016/06/22 16:37:30.62: 4 2: Server supports NT1 protocol
2016/06/22 16:37:30.63: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/22 16:37:30.67: 4 2: logon by Lewis succeeded
2016/06/22 16:37:30.68: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/22 16:37:30.80: 4 2:  tconx ok
2016/06/22 16:37:30.81: 9 2: NdpCreateConnection [0x671120] rc=0
2016/06/22 16:37:30.81: 9 2: NdpQueryPathInfo in [0x671120] <*>
2016/06/22 16:37:30.81: 9 2: NdpFindStart in [0x671120]
2016/06/22 16:37:30.81: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/06/22 16:37:30.81: 4 2:  smbwrp_echo
2016/06/22 16:37:30.90: 4 2:  smbwrp_filelist
2016/06/22 16:37:30.91: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/06/22 16:37:30.91: 1 2: list_files
2016/06/22 16:37:30.91: 9 2: dircache_list_files []
2016/06/22 16:37:30.91: 9 2: findDirCache: []
2016/06/22 16:37:30.91: 9 2: findDirCache: 0
2016/06/22 16:37:30.91: 9 2: CacheRead: [], 0
2016/06/22 16:37:30.91: 4 2: list_files level 260. mask <\*>
2016/06/22 16:37:34.42: 9 2: dircache_write_begin pdc 0x6257a0 path []
2016/06/22 16:37:34.42: 9 2: findDirCache: []
2016/06/22 16:37:34.42: 9 2: findDirCache: 0
2016/06/22 16:37:34.42: 9 2: CacheWriteBegin: 
2016/06/22 16:37:34.42: 9 2: dircache_write_begin returning ctx 0x672b80
2016/06/22 16:37:34.42: 4 2: list_files: got 103 files
2016/06/22 16:37:34.42: 4 2:  smbwrp_dir_add
2016/06/22 16:37:34.42: 8 2: adding <1040> 289 529564672 261
2016/06/22 16:37:34.43: 9 2: fname \1040
2016/06/22 16:37:34.43: 9 2: size 0
2016/06/22 16:37:34.43: 9 2: mtime 1292633962 Fri Dec 17 19:59:22 2010
2016/06/22 16:37:34.43: 9 2: ftimeLastAccess 19:59:22
2016/06/22 16:37:34.43: 9 2: dircache_write_entry 0x672b80
[...]
2016/06/22 16:37:34.82: 9 2: mtime 1292686078 Sat Dec 18 10:27:58 2010
2016/06/22 16:37:34.82: 9 2: ftimeLastAccess 10:27:58
2016/06/22 16:37:34.82: 9 2: dircache_write_entry 0x672b80
2016/06/22 16:37:34.82: 9 2: dircache_write_end: pdce 0x672b80
2016/06/22 16:37:34.82: 9 2: NdpFindStart <*> (\*) cnt 0 rc=0

wait approx 2 hours 25 minutes, and run again:

2016/06/22 19:02:30.38: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:30.39: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:30.39: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:30.40: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/06/22 19:02:30.40: 9 2: checkMountResource in tid#2
2016/06/22 19:02:30.40: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/22 19:02:30.40: 1 2: NTLMv1 Support enabled
2016/06/22 19:02:31.23: 4 2: Server supports NT1 protocol
2016/06/22 19:02:31.23: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/22 19:02:31.36: 4 2: logon by Lewis succeeded
2016/06/22 19:02:31.36: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/22 19:02:31.40: 4 2:  tconx ok
2016/06/22 19:02:31.40: 4 2:  smbwrp_dskattr
2016/06/22 19:02:31.43: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/06/22 19:02:31.43: 4 2:  smbwrp_disconnect
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryFSAllocate rc=87/rc1=0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo in
2016/06/22 19:02:31.47: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/22 19:02:31.47: 9 2: NdpQueryPathInfo in [0x671120] <*>
2016/06/22 19:02:31.47: 9 2: NdpFindStart in [0x671120]
2016/06/22 19:02:31.47: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/06/22 19:02:31.47: 4 2:  smbwrp_echo
2016/06/22 19:02:31.52: 4 2:  smbwrp_filelist
2016/06/22 19:02:31.52: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/06/22 19:02:31.52: 1 2: list_files
2016/06/22 19:02:31.52: 9 2: dircache_list_files []
2016/06/22 19:02:31.52: 9 2: findDirCache: []
2016/06/22 19:02:31.52: 9 2: findDirCache: entry []
2016/06/22 19:02:31.52: 9 2: dcePathEqualTo: [] []
2016/06/22 19:02:31.53: 9 2: findDirCache: 0x672b80
2016/06/22 19:02:31.53: 9 2: CacheRead: entry 0x672b80 found for []
2016/06/22 19:02:31.53: 9 2: CacheRead: expired
2016/06/22 19:02:31.53: 9 2: CacheRead: [], 0
2016/06/22 19:02:31.53: 4 2: list_files level 260. mask <\*>
2016/06/22 19:02:32.52: 9 2: dircache_write_begin pdc 0x6257a0 path []
2016/06/22 19:02:32.52: 9 2: findDirCache: []
2016/06/22 19:02:32.52: 9 2: findDirCache: 0
2016/06/22 19:02:32.53: 9 2: CacheWriteBegin: 
2016/06/22 19:02:32.53: 9 2: dircache_write_begin returning ctx 0x673ac0
2016/06/22 19:02:32.53: 4 2: list_files: got 103 files
2016/06/22 19:02:32.53: 4 2:  smbwrp_dir_add
2016/06/22 19:02:32.53: 8 2: adding <1040> 289 529564672 261
2016/06/22 19:02:32.53: 9 2: fname \1040
2016/06/22 19:02:32.53: 9 2: size 0
2016/06/22 19:02:32.53: 9 2: mtime 1292633962 Fri Dec 17 19:59:22 2010
2016/06/22 19:02:32.53: 9 2: ftimeLastAccess 19:59:22
2016/06/22 19:02:32.53: 9 2: dircache_write_entry 0x673ac0
[...]
2016/06/22 19:02:32.91: 9 2: mtime 1292686078 Sat Dec 18 10:27:58 2010
2016/06/22 19:02:32.91: 9 2: ftimeLastAccess 10:27:58
2016/06/22 19:02:32.91: 9 2: dircache_write_entry 0x673ac0
2016/06/22 19:02:32.91: 9 2: dircache_write_end: pdce 0x673ac0
2016/06/22 19:02:32.91: 9 2: NdpFindStart <*> (\*) cnt 0 rc=0

I'm certain we were losing the connection in under 2 hours before (more like 45 minutes to an hour, IIRC).

I'll keep this open and try the dir again in the morning, with the client sitting idle. If we get success then, I'll close this ticket as resolved.

Thanks, Paul!

comment:22 Changed 4 years ago by Paul Smedley

Hey Lewis.

The log above shows my fix had no impact here - ie it wasn't needed.

2016/06/22 19:02:31.47: 9 2: NdpFindStart?: dir [\], dir_mask [*], mask [\*], szPath [*] 2016/06/22 19:02:31.47: 4 2: smbwrp_echo 2016/06/22 19:02:31.52: 4 2: smbwrp_filelist

if smbwrp_echo - ie a ping to the server fails, the client will now automatically reconnect - this didn't happen in the above....

comment:23 Changed 4 years ago by Lewis Rosenthal

Okay, then.

I waited 10.5 hours, and in between, the VPN connection itself went down (power went out), though my client did not (on battery; thus, the control program was running continuously).

The dir command worked. Here is the log:

2016/06/23 10:37:09.37: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:09.40: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:09.40: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:09.40: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:09.41: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:09.41: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:09.41: 9 2: NdpRsrcQueryFSAllocate 0285fdd0
2016/06/23 10:37:09.41: 9 2: checkMountResource in tid#2
2016/06/23 10:37:09.41: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/23 10:37:09.41: 1 2: NTLMv1 Support enabled
2016/06/23 10:37:10.21: 4 2: Server supports NT1 protocol
2016/06/23 10:37:10.21: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/23 10:37:10.34: 4 2: logon by Lewis succeeded
2016/06/23 10:37:10.34: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/23 10:37:10.38: 4 2:  tconx ok
2016/06/23 10:37:10.38: 4 2:  smbwrp_dskattr
2016/06/23 10:37:10.48: 4 2: Error in cli_disk_size: NT_STATUS_INVALID_NETWORK_RESPONSE
2016/06/23 10:37:10.48: 4 2:  smbwrp_disconnect
2016/06/23 10:37:10.51: 9 2: NdpRsrcQueryFSAllocate rc=87/rc1=0 (cUnit = 123456/cUnitAvail = 123456/cbSector = 2048)
2016/06/23 10:37:10.51: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:10.51: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo in
2016/06/23 10:37:10.52: 9 2: NdpRsrcQueryInfo rc=0, s = SMBFS64 \\workgroup:othello\data@Lewis
2016/06/23 10:37:10.52: 9 2: NdpQueryPathInfo in [0x626260] <*>
2016/06/23 10:37:10.52: 9 2: NdpFindStart in [0x626260]
2016/06/23 10:37:10.52: 9 2: NdpFindStart: dir [\], dir_mask [*], mask [\*], szPath [*]
2016/06/23 10:37:10.52: 4 2:  smbwrp_echo
2016/06/23 10:37:10.52: 4 2: NdpFindStart, smbwrp_echo rc = -1, reconnecting.....
2016/06/23 10:37:10.52: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/23 10:37:10.52: 1 2: NTLMv1 Support enabled
2016/06/23 10:37:10.76: 4 2: Server supports NT1 protocol
2016/06/23 10:37:10.76: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/23 10:37:10.82: 4 2: logon by Lewis succeeded
2016/06/23 10:37:10.82: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/23 10:37:11.0: 4 2:  tconx ok
2016/06/23 10:37:11.0: 4 2:  smbwrp_filelist
2016/06/23 10:37:11.0: 1 2: Filelist <\*> on master <WORKGROUP> wgrp <workgroup> server <othello> share <data> clidev <A:>
2016/06/23 10:37:11.0: 1 2: list_files
2016/06/23 10:37:11.0: 9 2: dircache_list_files []
2016/06/23 10:37:11.0: 9 2: findDirCache: []
2016/06/23 10:37:11.0: 9 2: findDirCache: entry []
2016/06/23 10:37:11.0: 9 2: dcePathEqualTo: [] []
2016/06/23 10:37:11.0: 9 2: findDirCache: 0x671180
2016/06/23 10:37:11.0: 9 2: CacheRead: entry 0x671180 found for []
2016/06/23 10:37:11.0: 9 2: CacheRead: expired
2016/06/23 10:37:11.0: 9 2: CacheRead: [], 0
2016/06/23 10:37:11.0: 4 2: list_files level 260. mask <\*>
2016/06/23 10:37:12.45: 9 2: dircache_write_begin pdc 0x6257a0 path []
2016/06/23 10:37:12.45: 9 2: findDirCache: []
2016/06/23 10:37:12.45: 9 2: findDirCache: 0
2016/06/23 10:37:12.45: 9 2: CacheWriteBegin: 
2016/06/23 10:37:12.45: 9 2: dircache_write_begin returning ctx 0x6718e0
2016/06/23 10:37:12.45: 4 2: list_files: got 103 files
2016/06/23 10:37:12.45: 4 2:  smbwrp_dir_add
2016/06/23 10:37:12.45: 8 2: adding <1040> 289 764445696 261
2016/06/23 10:37:12.45: 9 2: fname \1040
2016/06/23 10:37:12.45: 9 2: size 0
2016/06/23 10:37:12.45: 9 2: mtime 1292633962 Fri Dec 17 19:59:22 2010
2016/06/23 10:37:12.45: 9 2: ftimeLastAccess 19:59:22
2016/06/23 10:37:12.45: 9 2: dircache_write_entry 0x6718e0
[...]

This time, I think we have it. See:

2016/06/23 10:37:10.52: 4 2:  smbwrp_echo
2016/06/23 10:37:10.52: 4 2: NdpFindStart, smbwrp_echo rc = -1, reconnecting.....
2016/06/23 10:37:10.52: 1 2: Connecting to \\Lewis:*********@workgroup:othello\data. Master WORKGROUP:1
2016/06/23 10:37:10.52: 1 2: NTLMv1 Support enabled
2016/06/23 10:37:10.76: 4 2: Server supports NT1 protocol
2016/06/23 10:37:10.76: 4 2:  session setuping for <Lewis>/<********> in <workgroup>
2016/06/23 10:37:10.82: 4 2: logon by Lewis succeeded
2016/06/23 10:37:10.82: 4 2:  session setup ok. Sending tconx <data> <********>
2016/06/23 10:37:11.0: 4 2:  tconx ok
2016/06/23 10:37:11.0: 4 2:  smbwrp_filelist

comment:24 Changed 4 years ago by Lewis Rosenthal

Resolution: fixed
Status: reopenedclosed

Closing this as fixed.

Note: See TracTickets for help on using tickets.