samba - May 2010 - fixed delay logging onto Samba3.3 from Vista Business

> The domain user does login eventually.  Mostly.  Roaming Profiles are
> very broken on W7: the top level "Vista.V2" directory is created,
but
> nothing is stored back into it on the server, and the logged in domain
> user ends up with a C:\Users\Temp profile. 
Thanks to Drew Vonada-Smith the roaming profiles are working again.  The
problem was that information stored in
HKLM\SOFTWARE\Microsoft\WindowsNT\CurrentVersion\Profilelist for the
user while trying logins while setting up the system got out of sync
with the actual server configuration.  Deleting the entry for any
existing users let them login with a functioning roaming profile. 
Unfortunately this did nothing about the fixed delays observed of 30s
and 15s.  Here is part of the netlogon.log for the slow parts of a
domain user with a working (small = 2.5MB) profile.  The 30s gap starts
at 10:05:53, and the 15s gap at 10:06:23.

05/27 10:05:51 [LOGON] SamLogon: Interactive logon of SAF\mathog from
SAF04 Entered
05/27 10:05:52 [LOGON] SamLogon: Interactive logon of SAF\mathog from
SAF04 Returns 0x0
05/27 10:05:52 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DS 
05/27 10:05:52 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:05:52 [MISC] NetpDcGetName: SAF: Only try once to find NT 5.0
DC in NT 4.0 domain.
05/27 10:05:52 [MAILSLOT] Sent 'Sam Logon' message to SAF[1C] on all
transports.
05/27 10:05:52 [CRITICAL] NetpDcMatchResponse: SAFSERVER: SAF: response
not from DS server. 0x0
05/27 10:05:52 [MISC] NetpDcGetName: NetpDcGetNameNetbios returned 121
05/27 10:05:52 [MISC] NetpDcGetName: SAF: Only try once done.
05/27 10:05:52 [MISC] NetpDcGetName: SAF: Domain is an NT 4.0 domain.
05/27 10:05:52 [MISC] DsGetDcName function returns 1355: Dom:SAF
Acct:(null) Flags: DS 
05/27 10:05:53 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DSP 
05/27 10:05:53 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:05:53 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain (Use previously cached entry.)
05/27 10:05:53 [MISC] DsGetDcName function returns 0: Dom:SAF
Acct:(null) Flags: DSP 
05/27 10:06:23 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DSP 
05/27 10:06:23 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:23 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain (Use previously cached entry.)
05/27 10:06:23 [MISC] DsGetDcName function returns 0: Dom:SAF
Acct:(null) Flags: DSP 
05/27 10:06:38 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: IP KDC 
05/27 10:06:38 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:38 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain
05/27 10:06:38 [MISC] DsGetDcName function returns 1355: Dom:SAF
Acct:(null) Flags: IP KDC 
05/27 10:06:38 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: IP KDC 
05/27 10:06:38 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:38 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain
05/27 10:06:38 [MISC] DsGetDcName function returns 1355: Dom:SAF
Acct:(null) Flags: IP KDC 
05/27 10:06:39 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DS NETBIOS RET_DNS 
05/27 10:06:39 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:39 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain
05/27 10:06:39 [MISC] DsGetDcName function returns 1355: Dom:SAF
Acct:(null) Flags: DS NETBIOS RET_DNS 
05/27 10:06:39 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DS RET_DNS 
05/27 10:06:39 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:39 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain
05/27 10:06:39 [MISC] DsGetDcName function returns 1355: Dom:SAF
Acct:(null) Flags: DS RET_DNS 
05/27 10:06:39 [MISC] DsGetDcName function called: Dom:SAF Acct:(null)
Flags: DSP 
05/27 10:06:39 [MISC] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is
c01ffff1
05/27 10:06:39 [MISC] NetpDcGetName: SAF: Avoid finding NT 5.0 DC in NT
4.0 domain (Use previously cached entry.)

I went through the event logs, and there was one interesting entry. 
Also at 10:05:53 in the system log there was an event 7001 (1101), 
"User Logon Notification for Customer Experience Improvement Program".
Have to run tcpdump on the server and see what happens at corresponding
times...

Nobody knows what causes these delays???

David Mathog
mathog at caltech.edu
Manager, Sequence Analysis Facility, Biology Division, Caltech

> I went through the event logs, and there was one interesting entry.
> Also at 10:05:53 in the system log there was an event 7001 (1101),
> "User Logon Notification for Customer Experience Improvement
Program".
> Have to run tcpdump on the server and see what happens at corresponding
> times...
>
> Nobody knows what causes these delays???
>
I just was looking for the cause of the 30 second to 1 minute delay
logging in to windows 7. No solution yet..

John

Marc Cain wrote:
> When the following local GPO is left in its default setting Samba
domain logons are delayed for 30 seconds: "Computer
Configuration\Administrative Templates\System\User Profiles\Set maximum
wait time for the network if the user has a roaming user profile or
remote home directory."  
> 
> Enable this and set the value to 0 to work around this timeout.  The
timeout does not occur when logging into an Active Directory PDC running
Server 2008 R2.  I have not tested this with w2k8 R2
client.
> 
> In addition, if the user's desktop is set to a solid background color
logons of any kind (local, AD, samba) will be delayed by 30 seconds. Set
the background to any .jpg image or apply Microsoft's hotfix to work
around this issue.  This is a cumulative timeout; that is, if the above
timeout is in affect and the solid background color timeout is also in
affect the delay is 60 seconds.

Oh crud, the background is solid.  On the other hand, the machine is
fully patched, so maybe that hotfix is already in place.

I ran wireshark on the client, and also had netlogon going.  Edited the
netlogon.log so that the times all ended in .000000 and saved the dump
in .csv format.  Merged them and sorted by time.  You can see the
results here:

  http://saf.bio.caltech.edu/pub/pickup/w7_logon_events.txt

The login starts with the netlogon 11:28:44.000000 entry.

Some interesting stuff in there.  There is an ARP request just before
the end of the 30 second gap in netlogon messages at 11:29:15.000000.
Just before that there are 5 seconds where no packets move between the
server and the client, in either direction. (131.215.12.42 / Gigabyte is
the workstations, 131.215.12.46 / Supermicro is the server.)
Why the heck is the client waiting for 30 seconds from the start of the 
session to look up the server's address, and why is it sending out an
ARP when the workstation had a TCP packet at 11:28:39.677891, only 35
seconds before?  Not to mention that in this case both the server and
workstation have static IP addresses!

The 15 second gap starting at 11:29:16 corresponds to 3 ICMP ping
requests from the client to the server, none of which trigger a response
packet.  Of course the server firewall is configured to drop all of
those - I bet allowing them will eliminate the 15 second delay. 
Possibly one of the configuration settings you mention would do the same.

Regards,

David Mathog
mathog at caltech.edu
Manager, Sequence Analysis Facility, Biology Division, Caltech

Marc Cain wrote:
> When the following local GPO is left in its default setting Samba
domain logons are delayed for 30 seconds: "Computer
Configuration\Administrative Templates\System\User Profiles\Set maximum
wait time for the network if the user has a roaming user profile or
remote home directory."  

Changed this (set to 0) and it knocked the logon time down to 22
seconds.  Checked the netlogon and wireshark logs and the 30 second gap
was gone.  However, the 15 second gap is still present, as are the
corresponding ICMP pings from the client to the server.  Have to modify
the server's firewall rules to allow icmp ping from the client unless
somebody knows where the registry key is that controls those pings.

Regards,

David Mathog
mathog at caltech.edu
Manager, Sequence Analysis Facility, Biology Division, Caltech

> However, the 15 second gap is still present, as are the
> corresponding ICMP pings from the client to the server.  Have to modify
> the server's firewall rules to allow icmp ping from the client unless
> somebody knows where the registry key is that controls those pings.
Found it!  
Domain login in 8 seconds!!!
One must enable "Do not detect slow network connections".  The method
it
uses to do that is to PING the server.  Not poke at one of the server
ports which should be open on the firewall, mind you, but do a regular
ICMP ping, which is of course blocked on 99.99% of all linux servers. 

The W7 client is currently set as follows;

1.  hosts entry for the samba server (probably not important)
2.  Do net detect slow network connections.  (Eliminates the 15s gap).
3.  Set max wait time for the network if the user has ... (Eliminates
the 30s gap)
4.  Do not check for user ownership of roaming profiles (possibly not
relevant).

Thanks to everybody who helped with this!

David Mathog
mathog at caltech.edu
Manager, Sequence Analysis Facility, Biology Division, Caltech