(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_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_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.