Bug 4945 - Winbind does not refresh Kerberos Tickets
Winbind does not refresh Kerberos Tickets
Status: NEW
Product: Samba 3.0
Classification: Unclassified
Component: winbind
3.0.26a
x64 Linux
: P3 normal
: none
Assigned To: Samba Bugzilla Account
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2007-08-31 08:46 UTC by Rick King
Modified: 2009-04-04 08:02 UTC (History)
2 users (show)

See Also:


Attachments
Winbind level 10 log (670.74 KB, text/plain)
2007-09-04 08:53 UTC, Rick King
no flags Details
Documentation patch more fully explaining the need for cached_login (2.19 KB, patch)
2007-09-19 13:44 UTC, Rick King
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Rick King 2007-08-31 08:46:03 UTC
With "winbind refresh tickets = yes" in smb.conf and

auth        required      pam_env.so
auth        sufficient    pam_unix.so nullok try_first_pass
auth        sufficient    pam_winbind.so use_first_pass krb5_auth krb5_ccache_type=FILE 

in pam.d/system-auth

Winbind correctly obtains Kerberos tickets upon logon however if a session is left open the tickets are not correctly renewed. It appears as if winbind attempts to renew the tickets and obtains new tickets which have the same expiry time as the previous tickets:

The relevant section of log.wb-DOMAIN (contiguous level 10 log):

[2007/08/23 00:12:44, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:12:53, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:12:57, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:12:59, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:13:00, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:13:01, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:13:01, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:13:01, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_943, DOMAIN+rdouglass
[2007/08/23 00:13:01, 3] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(155)
  krb5_ticket_refresh_handler: could not renew tickets: Ticket expired 


Klist after logon:

[rdouglass@pc ~]$ klist
Valid starting     Expires            Service principal
08/22/07 14:13:01  08/23/07 00:13:01  krbtgt/DOMAIN.COM@DOMAIN.COM
        renew until 08/23/07 00:13:01
08/22/07 14:13:01  08/23/07 00:13:01  pc$@DOMAIN.COM
        renew until 08/23/07 00:13:01


Kerberos 4 ticket cache: /tmp/tkt943
klist: You have no tickets cached

Klist the next morning:

[rdouglass@pc ~]$ klist
Ticket cache: FILE:/tmp/krb5cc_943
Default principal: rdouglass@DOMAIN.COM

Valid starting     Expires            Service principal
08/23/07 00:13:00  08/23/07 00:13:01  krbtgt/DOMAIN.COM@DOMAIN.COM
        renew until 08/23/07 00:13:01
Comment 1 Guenther Deschner 2007-09-03 07:11:10 UTC
Can you please post a log level = 10 log.wb-DOMAIN logfile ?
Comment 2 Rick King 2007-09-04 08:53:42 UTC
Created attachment 2918 [details]
Winbind level 10 log

This file is not from the same date/user but exhibits the same problem. Please refer to 05:21:37 in the log file to see the same effects as the log level 10 snippet already posted.

We currently have a test user group running with winbind authentication (3.0.25c). This bug is preventing us from rolling out winbind to the rest of our Linux users because it causing GNOME 'credential expired' warnings when users unlock their screens in the morning.
Comment 3 Gerald (Jerry) Carter 2007-09-04 09:04:51 UTC
Guenther, I've got an internal bug @ centeris logged against this as well.
I've had a hard time reproducing it.
Comment 4 Guenther Deschner 2007-09-04 10:06:35 UTC
Ok, had a deeper look on your logfiles. Thanks for that!

The timing of the refresh-event in winbind heavily depends on correct local time. 

Your winbindd writes to the logs that there is almost a 3h (!) clock-skew between the unix box and the windows dc. That is something winbindd cannot compensate.

Can you make sure to use centralized time services (like ntp against your windows dc) and see if there error persists?
Comment 5 Rick King 2007-09-04 11:00:08 UTC
Could you point me to the line/tell me what to search for to see this in the log file? I'm not sure why this has happened.

The error is happening on several machines. All of which are NTP time sync'd to a central server (and from there to pool.ntp.org servers). The local time on the machines has been correct. I cannot absolutely confirm that the DC's were synced. However, they currently report the correct time and are also NTP sync'd.


Comment 6 Rick King 2007-09-10 09:19:06 UTC
Hi,

Any progress on this? I can't find any evidence of time skew with any of our systems (more than a few milliseconds anyway).
Comment 7 Rick King 2007-09-17 08:42:40 UTC
I have now replicated this issue on Fedora Core 7.91 (32bit) with their supplied 3.0.26a rather than my custom compiled package for FC5 (now at 3.0.26a with the same issue).

On the FC 7.91 version the log entries for refreshing ticket absolutely flood the logs. Here's a snippet from 1 minute of logs (just before ticket expiry):

[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 10] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(92)
  krb5_ticket_refresh_handler called
  event called for: FILE:/tmp/krb5cc_10001, DOMAIN+rking
[2007/09/15 01:46:28, 3] nsswitch/winbindd_cred_cache.c:krb5_ticket_refresh_handler(155)
  krb5_ticket_refresh_handler: could not renew tickets: Ticket expired
Comment 8 Gerald (Jerry) Carter 2007-09-17 12:19:16 UTC
Do you have "cached_login = yes" in /etc/security/ppam_winbind.con?
Comment 9 Rick King 2007-09-17 12:29:48 UTC
There's nothing with winbind in it's name in /etc/security on the fc5 machines.

On FC 7.91 the file exists and has the line:
;cached_login = yes

In both cases winbind offline logon is not set in smb.conf.
Comment 10 Gerald (Jerry) Carter 2007-09-17 12:53:37 UTC
You have to set cached_login = yes in the pam config file to get
winbindd to cache the cleartext password in memory in order
to refresh tickets beyond the max lifetime.  
Comment 11 Rick King 2007-09-19 13:44:19 UTC
Created attachment 2926 [details]
Documentation patch more fully explaining the need for cached_login

Great, that seems to work. Thank you, I can now start to roll winbind out to our users. Such a simple solution too, I can't remember seeing this mentioned in any of the documentation. I didn't think to use cached_login because what I had read said it related to offline logins, which we are not going to use. I've attached a patch for the man pages.

Also, maybe an appropriate 'cannot renew ticket because no cached credentials exist' type error message could be added to the ticket renewal code?
Comment 12 Gerald (Jerry) Carter 2007-09-19 13:53:29 UTC
I recently ran across it and agree it is not inutitive.  The cached_login
option is being use for two different purposes which is a bad design.
I'll work on splitting this out to a new parameter in a future release.