Bjarne Maschoreck
2005-Jul-01 07:52 UTC
[Samba] Big authentification delays using winbind against ActiveDirectory ?
We use the winbind module in nsswitch.conf for authentification against
an ActiveDirectory. This works fine.
But it always takes around 10 seconds for a simple user authentification
(measured from the time the user has entered the password until the user
gets its shell). I am using Samba 3.0.20pre1 on SuSE 9.2, but we had the
same behaviour on version 3.0.9-2.3 (this newest version I could upgrade
to automatically on SuSE 9.2).
Why do I have this delay ?
Here some log snippets using debug level 10:
log.winbindd:
-------------
[2005/07/01 08:53:55, 10] sam/idmap_tdb.c:internal_get_id_from_sid(221)
internal_get_id_from_sid: fetching record
S-1-5-21-1112111302-854245398-725345543-513 of type 0x2
[2005/07/01 08:53:55, 10] sam/idmap_tdb.c:internal_get_id_from_sid(228)
internal_get_id_from_sid: record
S-1-5-21-2052111302-854245398-725345543-513 -> GID 10001
[2005/07/01 08:53:55, 10] sam/idmap_tdb.c:internal_get_id_from_sid(262)
internal_get_id_from_sid: ID_GROUPID fetching record
S-1-5-21-1112111302-854245398-725345543-513 -> GID 10001
[2005/07/01 08:53:55, 10] sam/idmap_tdb.c:internal_get_sid_from_id(190)
internal_get_sid_from_id: fetching record GID 10001
[2005/07/01 08:53:55, 10] sam/idmap_tdb.c:internal_get_sid_from_id(196)
internal_get_sid_from_id: fetching record GID 10001 ->
S-1-5-21-1112111302-854245398-725345543-513
[2005/07/01 08:53:55, 10] sam/idmap_util.c:idmap_sid_to_gid(181)
idmap_sid_to_gid: gid = [10001]
(!! note the 9 seconds here !!)
[2005/07/01 08:54:04, 10] nsswitch/winbindd.c:process_request(332)
process_request: request fn GETPWNAM
[2005/07/01 08:54:04, 3] nsswitch/winbindd_user.c:winbindd_getpwnam(312)
[ 0]: getpwnam icdadmin
[2005/07/01 08:54:04, 10]
nsswitch/winbindd_cache.c:cache_retrieve_response(1532)
Retrieving response for pid 23491
[2005/07/01 08:54:04, 10]
nsswitch/winbindd_cache.c:cache_retrieve_response(1532)
Retrieving response for pid 23491
[2005/07/01 08:54:04, 10] sam/idmap_util.c:idmap_sid_to_uid(144)
idmap_sid_to_uid: sid = [S-1-5-21-1112111302-854245398-725345543-26030]
log.wb-KK:
----------
[2005/07/01 08:53:55, 10]
nsswitch/winbindd_dual.c:child_process_request(537)
process_request: request fn DUAL_USERINFO
[2005/07/01 08:53:55, 3]
nsswitch/winbindd_user.c:winbindd_dual_userinfo(122)
[23489]: lookupsid S-1-5-21-1112111302-854245398-725345543-26030
[2005/07/01 08:53:55, 10]
nsswitch/winbindd_cache.c:refresh_sequence_number(354)
refresh_sequence_number: KK time ok
[2005/07/01 08:53:55, 10]
nsswitch/winbindd_cache.c:refresh_sequence_number(385)
refresh_sequence_number: KK seq number is now 2630844
[2005/07/01 08:53:55, 10] nsswitch/winbindd_cache.c:centry_expired(409)
centry_expired: Key U/S-1-5-21-1112111302-854245398-725345543-26030
for domain KK is good.
[2005/07/01 08:53:55, 10] nsswitch/winbindd_cache.c:wcache_fetch(488)
wcache_fetch: returning entry
U/S-1-5-21-1112111302-854245398-725345543-26030 for domain KK
[2005/07/01 08:53:55, 10] nsswitch/winbindd_cache.c:query_user(1090)
query_user: [Cached] - cached info for domain KK status Success
[2005/07/01 08:53:55, 10]
nsswitch/winbindd_cache.c:cache_store_response(1492)
Storing response for pid 23491, len 1300
(!! note the 9 seconds here !!)
[2005/07/01 08:54:04, 10] nsswitch/winbindd_dual.c:dual_client_read(69)
client_read: read 1828 bytes. Need 0 more for a full request.
[2005/07/01 08:54:04, 4] nsswitch/winbindd_dual.c:fork_domain_child(667)
child daemon request 19
[2005/07/01 08:54:04, 10]
nsswitch/winbindd_dual.c:child_process_request(537)
process_request: request fn LOOKUPNAME
[2005/07/01 08:54:04, 3]
nsswitch/winbindd_async.c:winbindd_dual_lookupname(695)
[23489]: lookupname KK@icdadmin
[2005/07/01 08:54:04, 10]
nsswitch/winbindd_cache.c:refresh_sequence_number(354)
refresh_sequence_number: KK time ok
[2005/07/01 08:54:04, 10]
nsswitch/winbindd_cache.c:refresh_sequence_number(385)
refresh_sequence_number: KK seq number is now 2630844
This is the smb.conf I use (global section settings only):
----------------------------------------------------------
workgroup = KK
realm = KK.LOCAL
security = ADS
use kerberos keytab = yes
# client use spnego = yes
map to guest = Bad User
username map = /etc/samba/smbusers
printcap cache time = 750
logon path = \\%L\profiles\.msprofile
logon drive = P:
logon home = \\%L\%U\.9xprofile
idmap uid = 10000-20000
idmap gid = 10000-20000
template homedir = /winhome/%U
template shell = /bin/bash
winbind separator = @
winbind use default domain = yes
winbind cache time = 900
winbind enum users = no
winbind enum groups = no
create mask = 0777
force create mode = 0660
directory mask = 0777
force directory mode = 0777
cups options = raw
include = /etc/samba/dhcp.conf
encrypt passwords = yes
guest account = visitor
server string = KK filserver
This is the smb.conf I use (global section settings only):
----------------------------------------------------------
[libdefaults]
clockskew = 300
default_realm = KK.LOCAL
[realms]
KK.LOCAL = {
kdc = ADMCONTROLLER
default_domain = KK.LOCAL
kpasswd_server = ADMCONTROLLER
}
[domain_realm]
.KK.LOCAL = KK.LOCAL
[logging]
default = SYSLOG:NOTICE:DAEMON
kdc = FILE:/var/log/kdc.log
kadmind = FILE:/var/log/kadmind.log
[appdefaults]
pam = {
ticket_lifetime = 1d
renew_lifetime = 1d
forwardable = true
proxiable = false
retain_after_close = false
minimum_uid = 0
debug = false
}
This delay behaviour happens all the time. What happens at the delay
period ? Who is to blame, the winbind or the ActiveDirectory ?
Thanks for your help!
rgds,
Bjarne Maschoreck