Following https://fedorahosted.org/sssd/wiki/Configuring%20sssd%20to%20authenticate%20... on Oracle Linux (RHEL clone) 6.3, 64-bit, sssd version 1.8.0 gets us all the way to the point where we can kinit with /etc/krb5.keytab and successfully run the test ldapsearch command. When we start sssd and try getent on a user in AD we get this to /var/log/messages:
"Jul 18 14:58:44 wardentest3 sssd_be: encoded packet size too big (813957120 > 16777215)"
Setting debug_level to 0x7850 (the highest, I believe) doesn't yield any additional helpful info.
I did deviate a bit from the SSSD/AD document in that I did not bind the host but instead created a keytab for a generic user we use to give our linux hosts access to LDAP on AD. I didn't think this would be a problem since the kinit/ldapsearch test worked fine.
Here's the safe bits of our keytab (we're using mailuser@W2K.GENESEO.EDU as our principal):
Keytab name: WRFILE:/etc/krb5.keytab KVNO Principal ---- -------------------------------------------------------------------------- 25 HOST/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HOST/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 mailuser@W2K.GENESEO.EDU (arcfour-hmac)
Google searches seemed to indicate that this may be some kind of sasl issue and possibly out of SSSD's control. Has anyone experience a similar problem or have advice on what to try?
-- David Warden Mail Administrator State University of New York at Geneseo
"There's only one rule that I know of, babies—God damn it, you've got to be kind."
On Wed, 2012-07-18 at 15:17 -0400, David Warden wrote:
Following https://fedorahosted.org/sssd/wiki/Configuring%20sssd%20to%20authenticate%20... on Oracle Linux (RHEL clone) 6.3, 64-bit, sssd version 1.8.0 gets us all the way to the point where we can kinit with /etc/krb5.keytab and successfully run the test ldapsearch command.
Would you mind please being more specific about the kinit and ldapsearch that you ran? I'm a bit surprised that ldapsearch would work if you get the below message on SSSD.
When we start sssd and try getent on a user in AD we get this to /var/log/messages:
"Jul 18 14:58:44 wardentest3 sssd_be: encoded packet size too big (813957120 > 16777215)"
From a quick Google search, it looks like this happens when Microsoft issues a PAC in the kerberos ticket that is too large for SASL to handle[1].
The size of the PAC is proportional to the number of users, groups and access-control permissions that are specified in the Windows Server. I'm not sure how complex your environment would have to be to hit that limit, but I suspect if anyone is going to hit it, a university would.
Unfortunately, I think this issue is outside SSSD's control. It's most likely occurring in the cyrus-sasl package.
Setting debug_level to 0x7850 (the highest, I believe) doesn't yield any additional helpful info.
Could you provide it anyway? Sometimes the debug logs are only visibly helpful to the developers (for example, knowing which phase of processing triggered a failure might at least provide us guidance on a workaround).
I did deviate a bit from the SSSD/AD document in that I did not bind the host but instead created a keytab for a generic user we use to give our linux hosts access to LDAP on AD. I didn't think this would be a problem since the kinit/ldapsearch test worked fine.
Well, that *may* work, depending on the permissions granted to that user. Not being a "computer" account may introduce odd bugs though.
It seems likely that the reason for the PAC being so large is that if you have a single user with permissions on all your Linux hosts, all of that data is going to be encoded in the PAC. So using a computer account instead of a user account (which generally only has a PAC with data about a single client machine) would probably avoid this issue.
Here's the safe bits of our keytab (we're using mailuser@W2K.GENESEO.EDU as our principal):
Keytab name: WRFILE:/etc/krb5.keytab KVNO Principal
25 HOST/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HOST/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 mailuser@W2K.GENESEO.EDU (arcfour-hmac)
Google searches seemed to indicate that this may be some kind of sasl issue and possibly out of SSSD's control. Has anyone experience a similar problem or have advice on what to try?
[1] http://blog.gmane.org/gmane.comp.encryption.kerberos.heimdal.general/month=2...
On Jul 18, 2012, at 3:38 PM, Stephen Gallagher wrote:
On Wed, 2012-07-18 at 15:17 -0400, David Warden wrote:
Following https://fedorahosted.org/sssd/wiki/Configuring%20sssd%20to%20authenticate%20... on Oracle Linux (RHEL clone) 6.3, 64-bit, sssd version 1.8.0 gets us all the way to the point where we can kinit with /etc/krb5.keytab and successfully run the test ldapsearch command.
Would you mind please being more specific about the kinit and ldapsearch that you ran? I'm a bit surprised that ldapsearch would work if you get the below message on SSSD.
====== Kinit and Klist ====== [root@wardentest3 sssd]# kinit -k -t /etc/krb5.keytab 'mailuser@W2K.GENESEO.EDU' [root@wardentest3 sssd]# klist Ticket cache: FILE:/tmp/krb5cc_0 Default principal: mailuser@W2K.GENESEO.EDU
Valid starting Expires Service principal 07/18/12 16:01:02 07/19/12 02:01:01 krbtgt/W2K.GENESEO.EDU@W2K.GENESEO.EDU renew until 07/25/12 16:01:02
====== LDAP Search ====== [root@wardentest3 sssd]# ldapsearch -H ldap://ad1.w2k.geneseo.edu -Y GSSAPI -N -b "dc=w2k,dc=geneseo,dc=edu" "(cn=mailuser)" dn SASL/GSSAPI authentication started SASL username: mailuser@W2K.GENESEO.EDU SASL SSF: 56 SASL data security layer installed. # extended LDIF # # LDAPv3 # base <dc=w2k,dc=geneseo,dc=edu> with scope subtree # filter: (cn=mailuser) # requesting: dn #
# mailuser, Users, w2k.geneseo.edu dn: CN=mailuser,CN=Users,DC=w2k,DC=geneseo,DC=edu
# search reference ref: ldap://w2k.geneseo.edu/CN=Configuration,DC=w2k,DC=geneseo,DC=edu
# search result search: 4 result: 0 Success
# numResponses: 3 # numEntries: 1 # numReferences: 1
When we start sssd and try getent on a user in AD we get this to /var/log/messages:
"Jul 18 14:58:44 wardentest3 sssd_be: encoded packet size too big (813957120 > 16777215)"
From a quick Google search, it looks like this happens when Microsoft issues a PAC in the kerberos ticket that is too large for SASL to handle[1].
The size of the PAC is proportional to the number of users, groups and access-control permissions that are specified in the Windows Server. I'm not sure how complex your environment would have to be to hit that limit, but I suspect if anyone is going to hit it, a university would.
Unfortunately, I think this issue is outside SSSD's control. It's most likely occurring in the cyrus-sasl package.
Setting debug_level to 0x7850 (the highest, I believe) doesn't yield any additional helpful info.
Could you provide it anyway? Sometimes the debug logs are only visibly helpful to the developers (for example, knowing which phase of processing triggered a failure might at least provide us guidance on a workaround).
I was stupid and didn't realize I should add debug_level to my [domain/*] section of the sssd.conf file, which is why I wasn't seeing "useful" debug entries. Just tried that out of curiosity and see what appears to be relevant entries.
ldap_child.log has a lot of:
(Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): total buffer size: 55 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): realm_str size: 15 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): got realm_str: W2K.GENESEO.EDU (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): princ_str size: 24 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): got princ_str: mailuser@W2K.GENESEO.EDU (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32533]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): total buffer size: 55 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): realm_str size: 15 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): got realm_str: W2K.GENESEO.EDU (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): princ_str size: 24 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): got princ_str: mailuser@W2K.GENESEO.EDU (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Wed Jul 18 16:13:55 2012) [[sssd[ldap_child[32534]]]] [unpack_buffer] (0x1000): lifetime: 86400
sssd_GSUAD.log ([domain/GSUAD]):
(Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sbus_dispatch] (0x4000): dbus conn: 10AA960 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'name not resolved' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_port_status] (0x1000): Port status of port 636 for server 'ad1.w2k.geneseo.edu' is 'neutral' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'name not resolved' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [resolv_is_address] (0x4000): [ad1.w2k.geneseo.edu] does not look like an IP address (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [resolv_gethostbyname_step] (0x2000): Querying files (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [resolv_gethostbyname_step] (0x2000): Querying files (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 5 seconds (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sss_ldap_init_send] (0x4000): Using file descriptor [34] for LDAP connection. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ad1.w2k.geneseo.edu:636/??base] with fd [34]. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x10b47c0], connected[1], ops[0x115d490], ldap[0x10b5330] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_parse_entry] (0x4000): OriginalDN: []. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x10b47c0], connected[1], ops[0x115d490], ldap[0x10b5330] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_rootdse_done] (0x4000): Got rootdse (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 81200739 (int: 81200739) (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service KERBEROS (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'name resolved' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_port_status] (0x1000): Port status of port 0 for server 'ad1.w2k.geneseo.edu' is 'neutral' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'name resolved' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [create_tgt_req_send_buffer] (0x1000): buffer size: 55 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [32533] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_handler_setup] (0x2000): Signal handler set up for pid [32533] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x10b47c0], connected[1], ops[(nil)], ldap[0x10b5330] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_sig_handler] (0x1000): Waiting for child [32533]. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x10b47c0], connected[1], ops[0x1164770], ldap[0x10b5330] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_handle_release] (0x2000): Trace: sh[0x10b47c0], connected[1], ops[0x1164770], ldap[0x10b5330], destructor_lock[0], release_memory[0] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_done] (0x4000): advising for connection retry #1 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_done] (0x4000): releasing operation connection (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'working' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_port_status] (0x1000): Port status of port 636 for server 'ad1.w2k.geneseo.edu' is 'neutral' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'working' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sss_ldap_init_send] (0x4000): Using file descriptor [34] for LDAP connection. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ad1.w2k.geneseo.edu:636/??base] with fd [34]. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x11368a0], connected[1], ops[0x1166740], ldap[0x115cc70] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_parse_entry] (0x4000): OriginalDN: []. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x11368a0], connected[1], ops[0x1166740], ldap[0x115cc70] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_rootdse_done] (0x4000): Got rootdse (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 81200740 (int: 81200740) (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service KERBEROS (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'working' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_port_status] (0x1000): Port status of port 0 for server 'ad1.w2k.geneseo.edu' is 'neutral' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [get_server_status] (0x1000): Status of server 'ad1.w2k.geneseo.edu' is 'working' (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [create_tgt_req_send_buffer] (0x1000): buffer size: 55 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [32534] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_handler_setup] (0x2000): Signal handler set up for pid [32534] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x11368a0], connected[1], ops[(nil)], ldap[0x115cc70] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [child_sig_handler] (0x1000): Waiting for child [32534]. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_done] (0x2000): Old USN: 81200739, New USN: 81200740 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5 (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_process_result] (0x2000): Trace: sh[0x11368a0], connected[1], ops[0x10b4880], ldap[0x115cc70] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_handle_release] (0x2000): Trace: sh[0x11368a0], connected[1], ops[0x10b4880], ldap[0x115cc70], destructor_lock[0], release_memory[0] (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_done] (0x4000): too many communication failures, giving up... (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_op_done] (0x4000): releasing operation connection (Wed Jul 18 16:13:55 2012) [sssd[be[GSUAD]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Wed Jul 18 16:13:58 2012) [sssd[be[GSUAD]]] [sbus_dispatch] (0x4000): dbus conn: 109DDC0 (Wed Jul 18 16:13:58 2012) [sssd[be[GSUAD]]] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:58 2012) [sssd[be[GSUAD]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [cleanup_users] (0x4000): Cache expiration is set to 0 days (Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x1152dc0
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x1168fc0
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Destroying timer event 0x1168fc0 "ltdb_timeout"
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Ending timer event 0x1152dc0 "ltdb_callback"
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x1170020
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x1165f80
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Destroying timer event 0x1165f80 "ltdb_timeout"
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): tevent: Ending timer event 0x1170020 "ltdb_callback"
(Wed Jul 18 16:13:59 2012) [sssd[be[GSUAD]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
and then sssd.log has:
(Wed Jul 18 16:13:48 2012) [sssd] [sbus_add_watch] (0x2000): 0x16ad5f0/0x16a8aa0 (13), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_add_watch] (0x2000): 0x16ba990/0x16acfc0 (15), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16ba990/0x16bad30 (15), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16ADB20 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16ba990/0x16bad30 (15), R/- (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16ba990/0x16acfc0 (15), -/W (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16ba990/0x16bad30 (15), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16ba990/0x16acfc0 (15), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16ADB20 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:48 2012) [sssd] [sbus_message_handler] (0x4000): Received SBUS method [RegisterService] (Wed Jul 18 16:13:48 2012) [sssd] [sbus_add_watch] (0x2000): 0x16b1210/0x16afc40 (16), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b1210/0x16afc90 (16), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B08B0 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_add_watch] (0x2000): 0x16b2000/0x16b1550 (17), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b2000/0x16b15a0 (17), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B1A50 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b2000/0x16b15a0 (17), R/- (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b2000/0x16b1550 (17), -/W (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b2000/0x16b15a0 (17), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b2000/0x16b1550 (17), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b1210/0x16afc90 (16), R/- (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b1210/0x16afc40 (16), -/W (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b1210/0x16afc90 (16), R/- (enabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_toggle_watch] (0x4000): 0x16b1210/0x16afc40 (16), -/W (disabled) (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B08B0 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:48 2012) [sssd] [sbus_message_handler] (0x4000): Received SBUS method [RegisterService] (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B1A50 (Wed Jul 18 16:13:48 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:48 2012) [sssd] [sbus_message_handler] (0x4000): Received SBUS method [RegisterService] (Wed Jul 18 16:13:58 2012) [sssd] [sbus_add_timeout] (0x2000): 0x16ad840 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_add_timeout] (0x2000): 0x16b0870 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_add_timeout] (0x2000): 0x16ad440 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_remove_timeout] (0x2000): 0x16ad440 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B08B0 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:58 2012) [sssd] [sbus_remove_timeout] (0x2000): 0x16b0870 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16B1A50 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching. (Wed Jul 18 16:13:58 2012) [sssd] [sbus_remove_timeout] (0x2000): 0x16ad840 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): dbus conn: 16ADB20 (Wed Jul 18 16:13:58 2012) [sssd] [sbus_dispatch] (0x4000): Dispatching.
To me what jumps out are the lines that say the ldap_result found nothing. I'm tempted to do a packet capture and see exactly what it's searching for. As far as these logs go, though, it looks like authentication is succeeding…
I did deviate a bit from the SSSD/AD document in that I did not bind the host but instead created a keytab for a generic user we use to give our linux hosts access to LDAP on AD. I didn't think this would be a problem since the kinit/ldapsearch test worked fine.
Well, that *may* work, depending on the permissions granted to that user. Not being a "computer" account may introduce odd bugs though.
It seems likely that the reason for the PAC being so large is that if you have a single user with permissions on all your Linux hosts, all of that data is going to be encoded in the PAC. So using a computer account instead of a user account (which generally only has a PAC with data about a single client machine) would probably avoid this issue.
Tomorrow I will try binding it and using the machine account with sssd to see if that makes things better. We have about 10k user accounts and quite a few of the other entities you mentioned having an effect on PAC size.
Here's the safe bits of our keytab (we're using mailuser@W2K.GENESEO.EDU as our principal):
Keytab name: WRFILE:/etc/krb5.keytab KVNO Principal
25 HOST/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HOST/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 mailuser@W2K.GENESEO.EDU (arcfour-hmac)
Google searches seemed to indicate that this may be some kind of sasl issue and possibly out of SSSD's control. Has anyone experience a similar problem or have advice on what to try?
[1] http://blog.gmane.org/gmane.comp.encryption.kerberos.heimdal.general/month=2... _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://fedorahosted.org/mailman/listinfo/sssd-users
-- David Warden Mail Administrator State University of New York at Geneseo
"There's only one rule that I know of, babies—God damn it, you've got to be kind."
On Wed, 2012-07-18 at 16:30 -0400, David Warden wrote:
====== [root@wardentest3 sssd]# ldapsearch -H ldap://ad1.w2k.geneseo.edu -Y GSSAPI -N -b "dc=w2k,dc=geneseo,dc=edu" "(cn=mailuser)" dn SASL/GSSAPI authentication started SASL username: mailuser@W2K.GENESEO.EDU SASL SSF: 56 SASL data security layer installed.
Ah ha! So here's the real issue. First, please note that you performed this test against ldap:// NOT ldaps://. Also, this connection used "SASL SSF: 56", which has the same effect as my other comment in this thread. Presumably, your system defaults specify this value, or you have it set in the /etc/openldap.conf. (Or possibly the AD server itself mandates it. All are possible reasons for this happening).
So really what happened when you tried to connect to LDAPS with "SASL SSF: 56" is that it tried to encrypt the communication with two different encryption protocols simultaneously.
So in conclusion, this will work and be encrypted over port 389.
On Jul 18, 2012, at 3:38 PM, Stephen Gallagher wrote:
On Wed, 2012-07-18 at 15:17 -0400, David Warden wrote:
Following https://fedorahosted.org/sssd/wiki/Configuring%20sssd%20to%20authenticate%20... on Oracle Linux (RHEL clone) 6.3, 64-bit, sssd version 1.8.0 gets us all the way to the point where we can kinit with /etc/krb5.keytab and successfully run the test ldapsearch command.
Would you mind please being more specific about the kinit and ldapsearch that you ran? I'm a bit surprised that ldapsearch would work if you get the below message on SSSD.
When we start sssd and try getent on a user in AD we get this to /var/log/messages:
"Jul 18 14:58:44 wardentest3 sssd_be: encoded packet size too big (813957120 > 16777215)"
From a quick Google search, it looks like this happens when Microsoft issues a PAC in the kerberos ticket that is too large for SASL to handle[1].
The size of the PAC is proportional to the number of users, groups and access-control permissions that are specified in the Windows Server. I'm not sure how complex your environment would have to be to hit that limit, but I suspect if anyone is going to hit it, a university would.
Unfortunately, I think this issue is outside SSSD's control. It's most likely occurring in the cyrus-sasl package.
Setting debug_level to 0x7850 (the highest, I believe) doesn't yield any additional helpful info.
Could you provide it anyway? Sometimes the debug logs are only visibly helpful to the developers (for example, knowing which phase of processing triggered a failure might at least provide us guidance on a workaround).
I did deviate a bit from the SSSD/AD document in that I did not bind the host but instead created a keytab for a generic user we use to give our linux hosts access to LDAP on AD. I didn't think this would be a problem since the kinit/ldapsearch test worked fine.
Well, that *may* work, depending on the permissions granted to that user. Not being a "computer" account may introduce odd bugs though.
It seems likely that the reason for the PAC being so large is that if you have a single user with permissions on all your Linux hosts, all of that data is going to be encoded in the PAC. So using a computer account instead of a user account (which generally only has a PAC with data about a single client machine) would probably avoid this issue.
Here's the safe bits of our keytab (we're using mailuser@W2K.GENESEO.EDU as our principal):
Keytab name: WRFILE:/etc/krb5.keytab KVNO Principal
25 HOST/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HOST/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 IMAP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 SMTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mail.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 HTTP/mailtest.geneseo.edu@W2K.GENESEO.EDU (arcfour-hmac) 25 mailuser@W2K.GENESEO.EDU (arcfour-hmac)
Google searches seemed to indicate that this may be some kind of sasl issue and possibly out of SSSD's control. Has anyone experience a similar problem or have advice on what to try?
[1] http://blog.gmane.org/gmane.comp.encryption.kerberos.heimdal.general/month=2... _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://fedorahosted.org/mailman/listinfo/sssd-users
While my 40kb+ post with log messages waits for admin approval, it is with great shame (and some joy) that I report that I was able to resolve my issue by changing to not connect to AD over LDAP+SSL (port 636) and instead connect to normal unencrypted LDAP on port 389. I am not sure why that would have made a difference and I would prefer to do this over SSL so I'm going to keep investigating but it is strange that this fixed the problem.
-- David Warden Mail Administrator State University of New York at Geneseo
"There's only one rule that I know of, babies—God damn it, you've got to be kind."
On Wed, 2012-07-18 at 16:37 -0400, David Warden wrote:
While my 40kb+ post with log messages waits for admin approval, it is with great shame (and some joy) that I report that I was able to resolve my issue by changing to not connect to AD over LDAP+SSL (port 636) and instead connect to normal unencrypted LDAP on port 389. I am not sure why that would have made a difference and I would prefer to do this over SSL so I'm going to keep investigating but it is strange that this fixed the problem.
David, 2 reasons why it may not work.
1. Windows Ad by default does not have SSL certs installed, so LDAPS is not usable unless you install certs.
2. Even when LDAPs is available, using GSSAPI auth usually implies using GSSAPI also for privacy (encryption). Windows does not support double encrypting channels (ie GSSAPI within SSL), so it would return an error.
If you want to use SSL for some reason (it is not necessary LDAP+GSSAPI is encrypted) then you need to tell SASL to turn off GSSAPI encryption.
Simo.
First, thank you Simo and Stephen for your assistance and patience. I really appreciate it.
On Jul 18, 2012, at 5:52 PM, Simo Sorce wrote:
On Wed, 2012-07-18 at 16:37 -0400, David Warden wrote:
While my 40kb+ post with log messages waits for admin approval, it is with great shame (and some joy) that I report that I was able to resolve my issue by changing to not connect to AD over LDAP+SSL (port 636) and instead connect to normal unencrypted LDAP on port 389. I am not sure why that would have made a difference and I would prefer to do this over SSL so I'm going to keep investigating but it is strange that this fixed the problem.
David, 2 reasons why it may not work.
- Windows Ad by default does not have SSL certs installed, so LDAPS is
not usable unless you install certs.
We have installed certs on all our AD controllers, mostly so we could do password change operations over LDAP.
- Even when LDAPs is available, using GSSAPI auth usually implies using
GSSAPI also for privacy (encryption). Windows does not support double encrypting channels (ie GSSAPI within SSL), so it would return an error.
If you want to use SSL for some reason (it is not necessary LDAP+GSSAPI is encrypted) then you need to tell SASL to turn off GSSAPI encryption.
I was unaware/confused about the privacy aspect of GSSAPI auth. Both your answer and Stephen's have been very enlightening! Thanks again. And thank you for your work on sssd.
Simo.
-- Simo Sorce * Red Hat, Inc * New York
sssd-users mailing list sssd-users@lists.fedorahosted.org https://fedorahosted.org/mailman/listinfo/sssd-users
On Jul 19, 2012, at 3:29 AM, Ondrej Valousek wrote:
I do not understand. If using Kerberos already, why would you need to do passwd changes over Ldap? O.
Perhaps I am mistaken again but we wanted a web app that users could use to change their password if they knew it or use some knowledge to reset their password if they forgot it in Active Directory. Everything I read on the subject indicated that had to be done over LDAP.
On 07/19/2012 03:06 AM, David Warden wrote:
We have installed certs on all our AD controllers, mostly so we could do password change operations over LDAP.
sssd-users mailing list sssd-users@lists.fedorahosted.org https://fedorahosted.org/mailman/listinfo/sssd-users
Well, I guess it should not be a big problem to run 'passwd' or 'kpasswd' (if omitting PAM modules) inside of a CGI or PHP script. Different story/thread though....:-)
Ondrej
On 07/19/2012 01:32 PM, David Warden wrote:
Perhaps I am mistaken again but we wanted a web app that users could use to change their password if they knew it or use some knowledge to reset their password if they forgot it in Active Directory. Everything I read on the subject indicated that had to be done over LDAP.
On Thu, 2012-07-19 at 14:24 +0200, Ondrej Valousek wrote:
Well, I guess it should not be a big problem to run 'passwd' or 'kpasswd' (if omitting PAM modules) inside of a CGI or PHP script. Different story/thread though.... :-)
Generally speaking, you want to avoid executing local binaries in externally-facing applications. Security issues and all that.
The LDAP approach can be handled in-process at least.
sssd-users@lists.fedorahosted.org
-
David Warden -
Ondrej Valousek -
Simo Sorce -
Stephen Gallagher