Description of problem: This is a regression; pam_winbind cached login works in samba-3.6.6/samba-3.6.8 for Fedora 17. i have pam_winbind.conf setup for cached logins: # # pam_winbind configuration file # # /etc/security/pam_winbind.conf # [global] # turn on debugging ;debug = no debug = yes # turn on extended PAM state debugging ;debug_state = no debug_state = yes # request a cached login if possible # (needs "winbind offline logon = yes" in smb.conf) cached_login = yes # authenticate using kerberos krb5_auth = yes # when using kerberos, request a "FILE" krb5 credential cache type # (leave empty to just do krb5 authentication but not have a ticket # afterwards) krb5_ccache_type = FILE # make successful authentication dependend on membership of one SID # (can also take a name) ;require_membership_of = # password expiry warning period in days warn_pwd_expire = 14 # omit pam conversations ;silent = no # create homedirectory on the fly mkhomedir = yes I have the system-auth-ac stack configured like so: #%PAM-1.0 # This file is auto-generated. # User changes will be destroyed the next time authconfig is run. auth required pam_env.so auth sufficient pam_fprintd.so auth sufficient pam_unix.so nullok try_first_pass auth requisite pam_succeed_if.so uid >= 1000 quiet auth sufficient pam_winbind.so cached_login use_first_pass krb5_auth auth required pam_deny.so account required pam_unix.so account sufficient pam_localuser.so account sufficient pam_succeed_if.so uid < 1000 quiet account [default=bad success=ok user_unknown=ignore] pam_winbind.so cached_login krb5_auth account required pam_permit.so password requisite pam_cracklib.so try_first_pass retry=3 type= password sufficient pam_unix.so sha512 shadow nullok try_first_pass use_authtok password sufficient pam_winbind.so cached_login use_authtok krb5_auth password required pam_deny.so session optional pam_keyinit.so revoke session required pam_limits.so -session optional pam_systemd.so session optional pam_mkhomedir.so session [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid session optional pam_winbind.so session required pam_unix.so I have smb.conf configured like so: winbind use default domain = yes winbind offline logon = true winbind refresh tickets = true winbind cache time = 86400 winbind reconnect delay = 3600 winbind rpc only = true winbind enum users = true winbind enum groups = true winbind expand groups = true kerberos method = secrets and keytab using smbcontrol; i take winbindd offline: sudo smbcontrol winbindd offline using pamtester; i verify the pam stack: pamtester system-auth-ac allen authenticate with winbindd offline, i get this response from pamtester: Password: pamtester: Authentication failure i see this in my /var/log/secure: Oct 19 18:39:17 8ball pamtester: pam_unix(system-auth-ac:auth): authentication failure; logname= uid=1000 euid=1000 tty= ruser= rhost= user=allen Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] ENTER: pam_sm_authenticate (flags: 0x0000) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x1e86230) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_USER) = "allen" (0x1e86250) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_AUTHTOK) = 0x1ea5e40 Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_CONV) = 0x1e86270 Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): getting password (0x00007391) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): pam_get_item returned a password Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): Verify user 'allen' Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: krb5_ccache_type 'FILE' Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: warn_pwd_expire '14' Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling krb5 login flag Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling cached login flag Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling request for a FILE krb5 ccache Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_SYSTEM_ERR (4), NTSTATUS: NT_STATUS_OBJECT_NAME_NOT_FOUND, Error message was: NT_STATUS_OBJECT_NAME_NOT_FOUND Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): internal module error (retval = PAM_SYSTEM_ERR(4), user = 'allen') Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] LEAVE: pam_sm_authenticate returning 4 (PAM_SYSTEM_ERR) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x1e86230) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_USER) = "allen" (0x1e86250) Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_AUTHTOK) = 0x1ea5e40 Oct 19 18:39:17 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1e860b0] STATE: ITEM(PAM_CONV) = 0x1e86270 I have tried both version of recent samba4/samba-4 builds. I have tried this with the samba4 builds from here: http://jdennis.fedorapeople.org/ipa-devel/ Version-Release number of selected component (if applicable): The shipped version of samba4 for Fedora 17: samba4-4.0.0-58alpha18.fc17.x86_64 samba4-client-4.0.0-58alpha18.fc17.x86_64 samba4-common-4.0.0-58alpha18.fc17.x86_64 samba4-dc-4.0.0-58alpha18.fc17.x86_64 samba4-dc-libs-4.0.0-58alpha18.fc17.x86_64 samba4-debuginfo-4.0.0-58alpha18.fc17.x86_64 samba4-devel-4.0.0-58alpha18.fc17.x86_64 samba4-libs-4.0.0-58alpha18.fc17.x86_64 samba4-pidl-4.0.0-58alpha18.fc17.x86_64 samba4-python-4.0.0-58alpha18.fc17.x86_64 samba4-test-4.0.0-58alpha18.fc17.x86_64 samba4-winbind-4.0.0-58alpha18.fc17.x86_64 samba4-winbind-clients-4.0.0-58alpha18.fc17.x86_64 samba4-winbind-krb5-locator-4.0.0-58alpha18.fc17.x86_64 the ipa-devel version of samba4 i tested for Fedora 17: samba4-4.0.0-139.fc17.rc1.x86_64 samba4-client-4.0.0-139.fc17.rc1.x86_64 samba4-common-4.0.0-139.fc17.rc1.x86_64 samba4-dc-4.0.0-139.fc17.rc1.x86_64 samba4-dc-libs-4.0.0-139.fc17.rc1.x86_64 samba4-debuginfo-4.0.0-139.fc17.rc1.x86_64 samba4-devel-4.0.0-139.fc17.rc1.x86_64 samba4-libs-4.0.0-139.fc17.rc1.x86_64 samba4-pidl-4.0.0-139.fc17.rc1.x86_64 samba4-python-4.0.0-139.fc17.rc1.x86_64 samba4-test-4.0.0-139.fc17.rc1.x86_64 samba4-winbind-4.0.0-139.fc17.rc1.x86_64 samba4-winbind-clients-4.0.0-139.fc17.rc1.x86_64 samba4-winbind-krb5-locator-4.0.0-139.fc17.rc1.x86_64 How reproducible: Every time i take winbind offline with smbcontrol or when i unplug the network cable. Steps to Reproduce: 1. install samba4 2. take winbind offline or disconnect from your network 3. try to login or test with pamtester Actual results: [lallen@8ball DECISIV]$ pamtester system-auth-ac allen authenticate Password: pamtester: Authentication failure Expected results: [lallen@8ball DECISIV]$ pamtester system-auth-ac allen authenticate Password: pamtester: successfully authenticated and in /var/log/secure: Oct 19 18:38:53 8ball pamtester: pam_unix(system-auth-ac:auth): authentication failure; logname= uid=1000 euid=1000 tty= ruser= rhost= user=allen Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] ENTER: pam_sm_authenticate (flags: 0x0000) Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x1b1e230) Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_USER) = "allen" (0x1b1e250) Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_AUTHTOK) = 0x1b3de40 Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_CONV) = 0x1b1e270 Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): getting password (0x00007391) Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): pam_get_item returned a password Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): Verify user 'allen' Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: krb5_ccache_type 'FILE' Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: warn_pwd_expire '14' Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling krb5 login flag Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling cached login flag Oct 19 18:38:53 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling request for a FILE krb5 ccache Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): request wbcLogonUser succeeded Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): user 'allen' granted access Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): request returned KRB5CCNAME: FILE:/tmp/krb5cc_16777216 Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): Returned user was 'allen' Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] LEAVE: pam_sm_authenticate returning 0 (PAM_SUCCESS) Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x1b1e230) Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_USER) = "allen" (0x1b3ed10) Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_AUTHTOK) = 0x1b3de40 Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: ITEM(PAM_CONV) = 0x1b1e270 Oct 19 18:38:54 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x1b1e0b0] STATE: DATA(PAM_WINBIND_LOGONSERVER) = "DC1" (0x1b42a00) Oct 19 18:38:54 8ball pamtester: PAM [pamh: 0x1b1e0b0] CLEAN: cleaning up PAM data 0x1b42a00 (error_status = 0) Additional info: i think this is due to Alexander notice about what it's taking to get samba 4 into Fedora w.r.t kerberos (i.e. MIT vs Heimdial), but that's just a hunch. http://lists.fedoraproject.org/pipermail/devel/2012-June/168253.html
using smbcontrol; i set winbindd debug to 5: sudo smbcontrol winbindd debug 5 [2012/10/19 18:39:08.296973, 3] ../source3/winbindd/winbindd_pam.c:1523(winbindd_dual_pam_auth) [ 2016]: dual pam auth DECISIV\allen [2012/10/19 18:39:08.297101, 0] ../source3/winbindd/winbindd_cache.c:335(centry_hash16) centry corruption? hash len (126) != 16 [2012/10/19 18:39:08.297241, 0] ../source3/winbindd/winbindd_cache.c:1340(wcache_get_creds) wcache_get_creds: bad entry for [CRED/S-1-5-21-922937882-3182838465-1742455321-1110] - deleting [2012/10/19 18:39:08.298515, 2] ../source3/winbindd/winbindd_pam.c:1764(winbindd_dual_pam_auth) Plain-text authentication for user DECISIV\allen returned NT_STATUS_OBJECT_NAME_NOT_FOUND (PAM: 4) [2012/10/19 18:39:08.298606, 4] ../source3/winbindd/winbindd_dual.c:1556(fork_domain_child) Finished processing child request 13 [2012/10/19 18:39:13.176493, 4] ../source3/winbindd/winbindd_dual.c:1548(fork_domain_child) child daemon request 13 [2012/10/19 18:39:13.176616, 3] ../source3/winbindd/winbindd_pam.c:1523(winbindd_dual_pam_auth) [ 2016]: dual pam auth DECISIV\allen [2012/10/19 18:39:13.176752, 2] ../source3/winbindd/winbindd_pam.c:1764(winbindd_dual_pam_auth) Plain-text authentication for user DECISIV\allen returned NT_STATUS_OBJECT_NAME_NOT_FOUND (PAM: 4) [2012/10/19 18:39:13.176820, 4] ../source3/winbindd/winbindd_dual.c:1556(fork_domain_child) Finished processing child request 13 [2012/10/19 18:39:17.456508, 4] ../source3/winbindd/winbindd_dual.c:1548(fork_domain_child) child daemon request 13 [2012/10/19 18:39:17.456636, 3] ../source3/winbindd/winbindd_pam.c:1523(winbindd_dual_pam_auth) [ 2016]: dual pam auth DECISIV\allen [2012/10/19 18:39:17.456771, 2] ../source3/winbindd/winbindd_pam.c:1764(winbindd_dual_pam_auth) Plain-text authentication for user DECISIV\allen returned NT_STATUS_OBJECT_NAME_NOT_FOUND (PAM: 4) [2012/10/19 18:39:17.456841, 4] ../source3/winbindd/winbindd_dual.c:1556(fork_domain_child) Finished processing child request 13 something in wcache_get_creds() or centry_hash16() is failing, perhaps? [2012/10/19 18:39:08.297101, 0] ../source3/winbindd/winbindd_cache.c:335(centry_hash16) centry corruption? hash len (126) != 16 [2012/10/19 18:39:08.297241, 0] ../source3/winbindd/winbindd_cache.c:1340(wcache_get_creds) wcache_get_creds: bad entry for [CRED/S-1-5-21-922937882-3182838465-1742455321-1110] - deleting [2012/10/19 18:39:08.298515, 2] ../source3/winbindd/winbindd_pam.c:1764(winbindd_dual_pam_auth) Plain-text authentication for user DECISIV\allen returned NT_STATUS_OBJECT_NAME_NOT_FOUND (PAM: 4)
I updated the samba4-4.0.0-140.fc18.rc1.src.rpm package to Samba 4 rc3 and this issue is still present. I noticed that there have been some minor changes to winbind_cache.c for Samaba 4. It's failing at line #1337 in winbind_cache.c http://gitweb.samba.org/?p=samba.git;a=blob;f=source3/winbindd/winbindd_cache.c;h=2c9dd4a9b3e19472e9cfd0ceaff1d1b669cb037c;hb=HEAD 1337 *cached_nt_pass = (const uint8 *)centry_hash16(centry, mem_ctx); 1338 if (*cached_nt_pass == NULL) { 1339 fstring sidstr; 1340 1341 sid_to_fstring(sidstr, sid); 1342 1343 /* Bad (old) cred cache. Delete and pretend we 1344 don't have it. */ 1345 DEBUG(0,("wcache_get_creds: bad entry for [CRED/%s] - deleting\n", 1346 sidstr)); 1347 wcache_delete("CRED/%s", sidstr); 1348 centry_free(centry); 1349 return NT_STATUS_OBJECT_NAME_NOT_FOUND; 1350 } *cached_nt_pass is always NULL in my case. It's always NULL because of line #333 in the same file, centry_hash16 always returns NULL: 326 static char *centry_hash16(struct cache_entry *centry, TALLOC_CTX *mem_ctx) 327 { 328 uint32 len; 329 char *ret; 330 331 len = centry_uint8(centry); 332 333 if (len != 16) { 334 DEBUG(0,("centry corruption? hash len (%u) != 16\n", 335 len )); 336 return NULL; 337 } len is never equals 16.
found same bug https://bugzilla.redhat.com/show_bug.cgi?id=834044
Also, you will have this pam_winbind error on systems where the network "plumbing" is coming up and systemd kicks up the Samba services while the network isn't fully up and ready. In this case, winbindd boots up in offline mode, causing auth to fail. You have to force it online with smbcontrol winbdindd online then auth will work.
Thanks for the bug report. I've fixed it, see upstream bug. Why are you using samba4 and not samba?
Hi Andreas, Well, I dunno. I use Evolution with MAPI support to login into Microsoft Exchange 2010 Server and some of it's RPMs (dash devels I think) were linked against the samba4-* RPMs. So I just updated them to see if my issue was fixed in RC3. This is also the reason why I moved from samba-3* RPMs in Fedora 17. I just don't want to muck with two generations of Samba, you know. Also, I am on Fedora 17. Wouldn't I have to build alot of RPMs for dependencies of Evolution (for samba4- to samba-4 transition)? I just thought the easiest thing to do was update/change your SRPMs (and rebuild) to RC3 and try that version. On another note, this bug is more serious than I thought. Basically when winbind checks it's cache it will get an error and take winbindd offline thereby preventing me from logging in. I will try out your patch in a few days and let you via this ticket. Thanks for the help!
Hi Andreas, I have added your patch to my samba4-* SRPM. I did have to wipe out the winbind cache files in /var/lib/samba. (winbindd_cache.tdb, winbindd_cache.tdb.bak and winbindd_cache.tdb.bak.old) Then I ran my test case: 1) using pamtester with winbindd online; authenticate 2) using pamtester with winbindd offline; authenticate and check for cached login message. pamtester output: [lallen@8ball samba]$ pamtester system-auth-ac allen authenticate Password: pamtester: successfully authenticated [lallen@8ball samba]$ pamtester system-auth-ac allen authenticate Password: Domain Controller unreachable, using cached credentials instead. Network resources may be unavailable pamtester: successfully authenticated [lallen@8ball samba]$ /var/log/secure output for success and cache entry creation: Oct 31 14:12:12 8ball pamtester: pam_unix(system-auth-ac:auth): authentication failure; logname=lallen uid=1000 euid=1000 tty= ruser= rhost= user=allen Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] ENTER: pam_sm_authenticate (flags: 0x0000) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0xe69230) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_USER) = "allen" (0xe69250) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_AUTHTOK) = 0xe89480 Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_CONV) = 0xe69270 Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): getting password (0x00007391) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): pam_get_item returned a password Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): Verify user 'allen' Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: krb5_ccache_type 'FILE' Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: warn_pwd_expire '14' Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling krb5 login flag Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling cached login flag Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling request for a FILE krb5 ccache Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): request wbcLogonUser succeeded Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): user 'allen' granted access Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): request returned KRB5CCNAME: FILE:/tmp/krb5cc_16777216 Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): Returned user was 'allen' Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] LEAVE: pam_sm_authenticate returning 0 (PAM_SUCCESS) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0xe69230) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_USER) = "allen" (0xe92d30) Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_AUTHTOK) = 0xe89480 Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: ITEM(PAM_CONV) = 0xe69270 Oct 31 14:12:12 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0xe690b0] STATE: DATA(PAM_WINBIND_LOGONSERVER) = "DC1" (0xe8a1d0) Oct 31 14:12:12 8ball pamtester: PAM [pamh: 0xe690b0] CLEAN: cleaning up PAM data 0xe8a1d0 (error_status = 0) /var/log/secure output of cached login: Oct 31 14:12:30 8ball pamtester: pam_unix(system-auth-ac:auth): authentication failure; logname=lallen uid=1000 euid=1000 tty= ruser= rhost= user=allen Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] ENTER: pam_sm_authenticate (flags: 0x0000) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x19da230) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_USER) = "allen" (0x19da250) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_AUTHTOK) = 0x19fa480 Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_CONV) = 0x19da270 Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): getting password (0x00007391) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): pam_get_item returned a password Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): Verify user 'allen' Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: krb5_ccache_type 'FILE' Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): CONFIG file: warn_pwd_expire '14' Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling krb5 login flag Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling cached login flag Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): enabling request for a FILE krb5 ccache Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): request wbcLogonUser succeeded Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): user 'allen' granted access Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): User allen logged on using cached credentials Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): request returned KRB5CCNAME: FILE:/tmp/krb5cc_16777216 Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): Returned user was 'allen' Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] LEAVE: pam_sm_authenticate returning 0 (PAM_SUCCESS) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_SERVICE) = "system-auth-ac" (0x19da230) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_USER) = "allen" (0x1a04e80) Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_AUTHTOK) = 0x19fa480 Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: ITEM(PAM_CONV) = 0x19da270 Oct 31 14:12:30 8ball pamtester: pam_winbind(system-auth-ac:auth): [pamh: 0x19da0b0] STATE: DATA(PAM_WINBIND_LOGONSERVER) = "DC1" (0x19fb1d0) Oct 31 14:12:30 8ball pamtester: PAM [pamh: 0x19da0b0] CLEAN: cleaning up PAM data 0x19fb1d0 (error_status = 0)
Andreas, I think there's still something wrong with the winbind cache. I am now getting this on ssh login: $ ssh 8ball.decisiv.net Last login: Thu Nov 1 01:03:31 2012 from 192.168.71.153 id: cannot find name for group ID 16777216 $ id uid=16777216(allen) gid=16777216 groups=16777216,981(mock),16777218,16777223,16777224,16777230,16777234,16777235,16777236,16777237,16777241,16777242,16777243,16777244,16777256,16777257,16777258,16777259 allen@8ball ~ $ wbinfo -u allen@8ball ~ $ wbinfo -g enterprise read-only domain controllers domain admins domain users domain guests domain computers domain controllers <SNIP> exchange all hosted organizations exchange windows permissions sql admins $ sudo cat /var/log/samba/log.winbindd [2012/10/31 14:11:13, 0] ../source3/winbindd/winbindd.c:1396(main) winbindd version 4.0.0rc3 started. Copyright Andrew Tridgell and the Samba Team 1992-2012 [2012/10/31 14:11:13.796043, 1] ../source3/lib/tdb_validate.c:480(tdb_validate_and_backup) tdb '/var/lib/samba/winbindd_cache.tdb' is valid [2012/10/31 14:11:13.798363, 1] ../source3/lib/tdb_validate.c:490(tdb_validate_and_backup) Created backup '/var/lib/samba/winbindd_cache.tdb.bak' of tdb '/var/lib/samba/winbindd_cache.tdb' [2012/11/01 01:02:42.061262, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Got sig[15] terminate (is_parent=1) [2012/11/01 01:02:42, 0] ../source3/winbindd/winbindd.c:1396(main) winbindd version 4.0.0rc3 started. Copyright Andrew Tridgell and the Samba Team 1992-2012 [2012/11/01 01:02:42.121787, 0] ../source3/winbindd/winbindd_cache.c:335(centry_hash16) centry corruption? hash len (198) != 16 [2012/11/01 01:02:42.127592, 1] ../source3/lib/tdb_validate.c:480(tdb_validate_and_backup) tdb '/var/lib/samba/winbindd_cache.tdb' is valid [2012/11/01 01:02:42.129605, 1] ../source3/lib/tdb_validate.c:490(tdb_validate_and_backup) Created backup '/var/lib/samba/winbindd_cache.tdb.bak' of tdb '/var/lib/samba/winbindd_cache.tdb' Notice the line: [2012/11/01 01:02:42.121787, 0] ../source3/winbindd/winbindd_cache.c:335(centry_hash16) centry corruption? hash len (198) != 16 from /var/log/messages: Nov 1 01:02:42 8ball winbindd[3687]: [2012/11/01 01:02:42.061262, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Nov 1 01:02:42 8ball winbindd[3875]: [2012/11/01 01:02:42.061338, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Nov 1 01:02:42 8ball winbindd[3875]: Got sig[15] terminate (is_parent=0) Nov 1 01:02:42 8ball winbindd[3687]: Got sig[15] terminate (is_parent=1) Nov 1 01:02:42 8ball winbindd[3877]: [2012/11/01 01:02:42.061376, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Nov 1 01:02:42 8ball winbindd[3689]: [2012/11/01 01:02:42.061349, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Nov 1 01:02:42 8ball winbindd[3876]: [2012/11/01 01:02:42.061373, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Nov 1 01:02:42 8ball winbindd[3877]: Got sig[15] terminate (is_parent=0) Nov 1 01:02:42 8ball winbindd[3689]: Got sig[15] terminate (is_parent=0) Nov 1 01:02:42 8ball winbindd[3876]: Got sig[15] terminate (is_parent=0) Nov 1 01:02:42 8ball winbindd[30072]: [2012/11/01 01:02:42.121787, 0] ../source3/winbindd/winbindd_cache.c:335(centry_hash16) Nov 1 01:02:42 8ball winbindd[30072]: centry corruption? hash len (198) != 16
this line has now started to show up in /var/log/samba/log.wb-DOMAIN [2012/10/31 15:12:25.088507, 1] ../source3/rpc_client/cli_pipe.c:473(cli_pipe_validate_current_pdu) ../source3/rpc_client/cli_pipe.c:473: RPC fault code WERR_ACCESS_DENIED received from host dc1.decisiv.net! [2012/11/01 01:02:42.061349, 0] ../source3/winbindd/winbindd.c:204(winbindd_sig_term_handler) Got sig[15] terminate (is_parent=0)
The patch has been updated upstream so that we don't change the cache on disk format.
http://koji.fedoraproject.org/koji/taskinfo?taskID=4655768 This build should fix it.
Andreas, I grabbed the changed patch and built new RPMs. I will let you know if I encounter any more issues. Thanks for the help.
Is this fixed?
Andreas, Yes. I have been running Samba 4 (samba-4.0.1-1.fc17.x86_64) on Fedora 17 since it's release without any winbind cache troubles. Thanks!
Thanks. Closing the bug report.