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...
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(a)W2K.GENESEO.EDU'
[root@wardentest3 sssd]# klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: mailuser(a)W2K.GENESEO.EDU
Valid starting Expires Service principal
07/18/12 16:01:02 07/19/12 02:01:01 krbtgt/W2K.GENESEO.EDU(a)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(a)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(a)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(a)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(a)W2K.GENESEO.EDU as
our principal):
>
> Keytab name: WRFILE:/etc/krb5.keytab
> KVNO Principal
> ---- --------------------------------------------------------------------------
> 25 HOST/mail.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 HOST/mailtest.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 IMAP/mail.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 IMAP/mailtest.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 SMTP/mail.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 SMTP/mailtest.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 HTTP/mail.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 HTTP/mailtest.geneseo.edu(a)W2K.GENESEO.EDU (arcfour-hmac)
> 25 mailuser(a)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/mont...
_______________________________________________
sssd-users mailing list
sssd-users(a)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."