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%20with%20a%20Windows%202008%20Domain%20Server 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=20091101
_______________________________________________
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."