[Samba] Big authentification delays using winbind against ActiveDirectory ?

Fri Jul 1 07:52:04 GMT 2005

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 at 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