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
Can you please post a log level = 10 log.wb-DOMAIN logfile ?
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.
Guenther, I've got an internal bug @ centeris logged against this as well. I've had a hard time reproducing it.
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?
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.
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).
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
Do you have "cached_login = yes" in /etc/security/ppam_winbind.con?
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.
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.
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?
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.