Bug 868457
Summary: | pam_winbind cached login failing for samba4-* and samba-4.* builds | ||
---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | Allen Hewes <allen> |
Component: | samba4 | Assignee: | Andreas Schneider <asn> |
Status: | CLOSED CURRENTRELEASE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
Severity: | high | Docs Contact: | |
Priority: | unspecified | ||
Version: | 17 | CC: | abokovoy, asn, gdeschner, sbose, ssorce |
Target Milestone: | --- | ||
Target Release: | --- | ||
Hardware: | Unspecified | ||
OS: | Unspecified | ||
Whiteboard: | |||
Fixed In Version: | Doc Type: | Bug Fix | |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2013-02-11 12:49:48 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: |
Description
Allen Hewes
2012-10-19 23:06:05 UTC
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. |