samba - Sep 2013 - Samba 3.6.9 on Centos 6.4 and very slow first access to fileserver

Hello good people,

I am fighting with following issue: our users are complaining about very 
slow/delayed displaying of main folders during accessing server using 
\\dns.name.of.server (using \\IP or \\netbios_name is it with same 
slowness). But once they are authenticated, displaying contents of 
(sub-)folders are getting normal.

Once the user hit "enter" key on "\\dns.name.of.server" it
takes
approximately 20seconds till the user is requested for credentials. This 
twenty seconds is delay if user is accessing this server from Windows XP 
computer. But if he is using Windows 7, the delay is only ~10 second 
longer (but also it considered as long).

Server is in "domain" role, which means that authentication is passed 
toward primary controler - which is also samba (same OS, samba version) 
with LDAP backend. It does not matter to delay if "password server" 
directive is defined or not on this domain member server.

Here is the corresponding log (log level 3) part:

[2013/09/04 22:38:51.733770,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:38:51.736953,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:38:51.737608,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:38:51.756622,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:38:56.820935,  3] auth/auth.c:219(check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[WORKSTATION]\[username]@[WORKSTATION] with the new password interface
[2013/09/04 22:38:56.822654,  3] auth/auth.c:222(check_ntlm_password)
   check_ntlm_password:  mapped user is: [COMPANY]\[username]@[WORKSTATION]
[2013/09/04 22:38:56.823888,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:38:56.830032,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:38:56.831678,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:38:56.832574,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:01.954252,  0] 
auth/auth_domain.c:331(domain_client_validate)
   domain_client_validate: unable to validate password for user username 
in domain WORKSTATION to Domain controller FILEZA. Error was 
NT_STATUS_NO_SUCH_USER.
[2013/09/04 22:39:01.962686,  2] auth/auth.c:319(check_ntlm_password)
   check_ntlm_password:  Authentication for user [username] -> 
[username] FAILED with error NT_STATUS_NO_SUCH_USER
[2013/09/04 22:39:01.963542,  3] smbd/error.c:81(error_packet_set)
   error packet at smbd/sesssetup.c(124) cmd=115 (SMBsesssetupX) 
NT_STATUS_LOGON_FAILURE
[2013/09/04 22:39:01.967732,  3] smbd/server_exit.c:181(exit_server_common)
   Server exit (failed to receive smb request)
[2013/09/04 22:39:01.992663,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:39:01.995260,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:39:01.995722,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:39:01.995950,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:07.057852,  3] auth/auth.c:219(check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[WORKSTATION]\[username]@[WORKSTATION] with the new password interface
[2013/09/04 22:39:07.059742,  3] auth/auth.c:222(check_ntlm_password)
   check_ntlm_password:  mapped user is: [COMPANY]\[username]@[WORKSTATION]
[2013/09/04 22:39:07.061071,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:39:07.068083,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:39:07.069450,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:39:07.070099,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:07.074267,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 139
[2013/09/04 22:39:12.200887,  0] 
auth/auth_domain.c:331(domain_client_validate)
   domain_client_validate: unable to validate password for user username 
in domain WORKSTATION to Domain controller FILEZA. Error was 
NT_STATUS_NO_SUCH_USER.
[2013/09/04 22:39:12.206915,  2] auth/auth.c:319(check_ntlm_password)
   check_ntlm_password:  Authentication for user [username] -> 
[username] FAILED with error NT_STATUS_NO_SUCH_USER
[2013/09/04 22:39:12.207533,  3] smbd/error.c:81(error_packet_set)
   error packet at smbd/sesssetup.c(124) cmd=115 (SMBsesssetupX) 
NT_STATUS_LOGON_FAILURE
[2013/09/04 22:39:12.226398,  3] smbd/server_exit.c:181(exit_server_common)
   Server exit (failed to receive smb request)
[2013/09/04 22:39:12.265252,  3] auth/auth.c:219(check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[WORKSTATION]\[username]@[WORKSTATION] with the new password interface
[2013/09/04 22:39:12.265747,  3] auth/auth.c:222(check_ntlm_password)
   check_ntlm_password:  mapped user is: [COMPANY]\[username]@[WORKSTATION]
[2013/09/04 22:39:12.267007,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:39:12.271771,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:39:12.273839,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:39:12.274794,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:17.403826,  0] 
auth/auth_domain.c:331(domain_client_validate)
   domain_client_validate: unable to validate password for user username 
in domain WORKSTATION to Domain controller FILEZA. Error was 
NT_STATUS_NO_SUCH_USER.
[2013/09/04 22:39:17.411754,  2] auth/auth.c:319(check_ntlm_password)
   check_ntlm_password:  Authentication for user [username] -> 
[username] FAILED with error NT_STATUS_NO_SUCH_USER
[2013/09/04 22:39:17.412625,  3] smbd/error.c:81(error_packet_set)
   error packet at smbd/sesssetup.c(124) cmd=115 (SMBsesssetupX) 
NT_STATUS_LOGON_FAILURE
[2013/09/04 22:39:17.422294,  3] smbd/process.c:1662(process_smb)
   Transaction 3 of length 240 (0 toread)
[2013/09/04 22:39:17.422853,  3] smbd/process.c:1467(switch_message)
   switch message SMBsesssetupX (pid 5516) conn 0x0
[2013/09/04 22:39:17.424364,  3] 
smbd/sesssetup.c:1333(reply_sesssetup_and_X)
   wct=12 flg2=0xc807
[2013/09/04 22:39:17.424864,  2] smbd/sesssetup.c:1279(setup_new_vc_session)
   setup_new_vc_session: New VC == 0, if NT4.x compatible we would close 
all old resources.
[2013/09/04 22:39:17.425557,  3] 
smbd/sesssetup.c:1065(reply_sesssetup_and_X_spnego)
   Doing spnego session setup
[2013/09/04 22:39:17.426033,  3] 
smbd/sesssetup.c:1107(reply_sesssetup_and_X_spnego)
   NativeOS=[Windows 2002 Service Pack 3 2600] NativeLanMan=[Windows 
2002 5.1] PrimaryDomain=[]
[2013/09/04 22:39:17.427371,  3] 
smbd/sesssetup.c:660(reply_spnego_negotiate)
   reply_spnego_negotiate: Got secblob of size 40
[2013/09/04 22:39:17.427927,  3] 
../libcli/auth/ntlmssp.c:34(debug_ntlmssp_flags)
   Got NTLMSSP neg_flags=0xa2088207
[2013/09/04 22:39:17.429631,  3] smbd/process.c:1662(process_smb)
   Transaction 4 of length 332 (0 toread)
[2013/09/04 22:39:17.430096,  3] smbd/process.c:1467(switch_message)
   switch message SMBsesssetupX (pid 5516) conn 0x0
[2013/09/04 22:39:17.430880,  3] 
smbd/sesssetup.c:1333(reply_sesssetup_and_X)
   wct=12 flg2=0xc807
[2013/09/04 22:39:17.431578,  2] smbd/sesssetup.c:1279(setup_new_vc_session)
   setup_new_vc_session: New VC == 0, if NT4.x compatible we would close 
all old resources.
[2013/09/04 22:39:17.432038,  3] 
smbd/sesssetup.c:1065(reply_sesssetup_and_X_spnego)
   Doing spnego session setup
[2013/09/04 22:39:17.432818,  3] 
smbd/sesssetup.c:1107(reply_sesssetup_and_X_spnego)
   NativeOS=[Windows 2002 Service Pack 3 2600] NativeLanMan=[Windows 
2002 5.1] PrimaryDomain=[]
[2013/09/04 22:39:17.433521,  3] 
../libcli/auth/ntlmssp_server.c:348(ntlmssp_server_preauth)
   Got user=[username] domain=[WORKSTATION] workstation=[WORKSTATION] 
len1=24 len2=24
[2013/09/04 22:39:17.434898,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:39:17.440284,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:39:17.440892,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:39:17.441561,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:22.510591,  3] auth/auth.c:219(check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[WORKSTATION]\[username]@[WORKSTATION] with the new password interface
[2013/09/04 22:39:22.511547,  3] auth/auth.c:222(check_ntlm_password)
   check_ntlm_password:  mapped user is: [COMPANY]\[username]@[WORKSTATION]
[2013/09/04 22:39:22.512683,  3] libsmb/namequery.c:2533(get_dc_list)
   get_dc_list: preferred server list: "FILEZA, *"
[2013/09/04 22:39:22.516963,  3] libsmb/namequery_dc.c:204(rpc_dc_name)
   rpc_dc_name: Returning DC FILEZA (10.31.155.247) for domain COMPANY
[2013/09/04 22:39:22.578989,  3] 
libsmb/cliconnect.c:3172(cli_start_connection)
   Connecting to host=FILEZA
[2013/09/04 22:39:22.579701,  3] lib/util_sock.c:766(open_socket_out_send)
   Connecting to 10.31.155.247 at port 445
[2013/09/04 22:39:27.713051,  0] 
auth/auth_domain.c:331(domain_client_validate)
   domain_client_validate: unable to validate password for user username 
in domain WORKSTATION to Domain controller FILEZA. Error was 
NT_STATUS_NO_SUCH_USER.
[2013/09/04 22:39:27.718688,  2] auth/auth.c:319(check_ntlm_password)
   check_ntlm_password:  Authentication for user [username] -> 
[username] FAILED with error NT_STATUS_NO_SUCH_USER
[2013/09/04 22:39:27.719545,  3] smbd/error.c:81(error_packet_set)
   error packet at smbd/sesssetup.c(124) cmd=115 (SMBsesssetupX) 
NT_STATUS_LOGON_FAILURE
[2013/09/04 22:39:27.737415,  3] smbd/server_exit.c:181(exit_server_common)
   Server exit (failed to receive smb request)
-----------> here comes credentials request window on client computer.

as you can see the time from entering the connection till the 
user/password request is almost half minute.

Explanations:
- WORKSTATION - is windows client computer (in our case it is windows XP 
SP3)
-  FILEZA - is PDC (IP: 10.31.155.247) - mentioned before
- COMPANY - is samba domain name

here is configuration part of domain member server:

[global]
         workgroup = COMPANY
         server string = Samba List Server
         netbios name = FILE
         interfaces = lo eth0
         hosts allow = 127. 10.
         hosts deny = 0.0.0.0/0
         socket options = TCP_NODELAY SO_RCVBUF=8192 SO_SNDBUF=8192
         deadtime = 10
         # logs split per machine
         log file = /var/log/samba/%m.log
         # max 50KB per log file, then rotate
         max log size = 550
         log level = 3
         security = domain
         map untrusted to domain = yes
         local master = no
         os level = 22
         preferred master = no
         wins support = no
         wins server = 10.31.155.247
         name resolve order = wins bcast
         load printers = no
         cups options = raw
         printcap name = /dev/null
         host msdfs = yes

[sales]
msdfs proxy = \10.31.155.247\sales
msdfs root = yes
[iso]
msdfs proxy = \10.31.155.247\iso
msdfs root = yes
[support]
msdfs proxy = \10.31.155.247\support
msdfs root = yes
...

As you can see, there are _four_ "NT_STATUS_LOGON_FAILURE" even before
the client is challenged to provide credentials - why four times? I 
understand, that the windows client tries to use cached credentials of 
currently logged user, but why four times?
Do you have any idea what can be that bottleneck which is causing this 
delay?


thanks for any help on this

michal

On Wed, Sep 4, 2013 at 4:16 PM, Michal Bruncko <michal.bruncko at
gmail.com>wrote:
> socket options = TCP_NODELAY SO_RCVBUF=8192 SO_SNDBUF=8192

I'd start with commenting out that line and see if things get better.. then
check also with (on the samba machine) smbclient //localhost/share -d10
-Uusername and see if you can get any more info. Also from the samba
machine check and see if smbclient //10.31.155.247/support -d10 -Uusername
is helpful. Maybe something will give you a clue.