Attachment 851732 Details for Bug 1054899 – domain log for non-primary(user1_dom3) user login

domain log for non-primary(user1_dom3) user login

user1_dom3_sssd_sssdad.com.log (text/plain), 139.45 KB, created by Kaushik Banerjee on 2014-01-17 17:39:58 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Kaushik Banerjee

Created: 2014-01-17 17:39:58 UTC

Size: 139.45 KB

patch

obsolete

>(Fri Jan 17 06:39:25 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:39:25 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:25 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Jan 17 06:39:35 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:39:35 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:35 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f3a7a0
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][name=user1_dom3]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [be_req_set_domain] (0x0400): Changing request domain from [sssdad.com] to [child1.sssdad.com]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sdap_idmap_add_domain] (0x1000): Adding domain [S-1-5-21-2153326666-2176343378-3404031434] as slice [3853]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sysdb_idmap_dn] (0x4000): objectSID=S-1-5-21-2153326666-2176343378-3404031434,cn=id_mappings,cn=sssdad.com,cn=sysdb
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f52550
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f50a20
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f52550 "ltdb_callback"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f50a20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f52550 "ltdb_callback"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sysdb_idmap_store_mapping] (0x0100): Adding new ID mapping [sssdad.com][S-1-5-21-2153326666-2176343378-3404031434][3853]
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f3ff50
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f40080
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f3ff50 "ltdb_callback"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f40080 "ltdb_timeout"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f3ff50 "ltdb_callback"
>
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): beginning to connect
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD_GC'
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'neutral'
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain sssdad.com
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'sssdad.com'
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.sssdad.com'
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing...
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ad_get_dc_servers_done] (0x0400): Found 1 domain controllers in domain sssdad.com
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [sdap_connect_host_send] (0x0400): Resolving host pluto.sssdad.com
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_is_address] (0x4000): [pluto.sssdad.com] does not look like an IP address
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'pluto.sssdad.com' in files
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'pluto.sssdad.com' in files
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'pluto.sssdad.com' in DNS
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:37 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://pluto.sssdad.com:389
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x4000): Using file descriptor [23] for LDAP connection.
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://pluto.sssdad.com:389/??base] with fd [23].
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://pluto.sssdad.com:389
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=sssdad.com)(NtVer=\14\00\00\00))][].
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f40010], connected[1], ops[0x7ff269f62d50], ldap[0x7ff269f59f60]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netlogon]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f40010], connected[1], ops[0x7ff269f62d50], ldap[0x7ff269f59f60]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x7ff269f40010], connected[1], ops[(nil)], ldap[0x7ff269f59f60], destructor_lock[0], release_memory[0]
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [ad_get_client_site_done] (0x0400): Found site: Default-First-Site-Name
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_site_done] (0x0400): About to discover primary and backup servers
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [fo_discover_servers_send] (0x0400): Looking up primary servers
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'gc'. Will use DNS discovery domain 'Default-First-Site-Name._sites.sssdad.com'
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_gc._tcp.Default-First-Site-Name._sites.sssdad.com'
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:38 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing...
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got 3 servers
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_discover_servers_primary_done] (0x0400): Looking up backup servers
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'gc'. Will use DNS discovery domain 'sssdad.com'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_gc._tcp.sssdad.com'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing...
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got 3 servers
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_servers_done] (0x0400): Got 3 primary and 3 backup servers
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Inserted primary server 'pluto.sssdad.com:3268' to service 'AD_GC'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Inserted primary server 'longhaul.child1.sssdad.com:3268' to service 'AD_GC'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Inserted primary server 'eagle.sssdad_tree.com:3268' to service 'AD_GC'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Server 'longhaul.child1.sssdad.com:3268' for service 'AD_GC' is already present
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Server 'pluto.sssdad.com:3268' for service 'AD_GC' is already present
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Server 'eagle.sssdad_tree.com:3268' for service 'AD_GC' is already present
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'AD_GC' as 'resolved'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x0200): Found address for server pluto.sssdad.com: [10.65.206.100] TTL 3600
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://pluto.sssdad.com'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://pluto.sssdad.com:3268'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x4000): Using file descriptor [23] for LDAP connection.
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://pluto.sssdad.com:3268/??base] with fd [23].
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f71640], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f71640], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [currentTime]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [subschemaSubentry]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dsServiceName]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [schemaNamingContext]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [rootDomainNamingContext]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPPolicies]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [highestCommittedUSN]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dnsHostName]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ldapServiceName]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverName]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedCapabilities]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isSynchronized]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isGlobalCatalogReady]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainFunctionality]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [forestFunctionality]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainControllerFunctionality]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f71640], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_done] (0x2000): Got rootdse
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 672395 (int: 672395)
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [4]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_kinit_send] (0x0400): Attempting kinit (default, AMD-PIKE-05$, SSSDAD.COM, 86400)
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service AD
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x0200): Found address for server pluto.sssdad.com: [10.65.206.100] TTL 3600
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://pluto.sssdad.com'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://pluto.sssdad.com'
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 38
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [896]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [896]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[(nil)], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:39 2014) [sssd[be[sssdad.com]]] [write_pipe_handler] (0x0400): All data has been sent!
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x1000): Waiting for child [896].
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x0100): child [896] finished successfully.
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_SSSDAD.COM], expired on [1389994780]
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1389959680
>(Fri Jan 17 06:39:40 2014) [sssd[be[sssdad.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: AMD-PIKE-05$
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0100): Marking port 3268 of server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [set_server_common_status] (0x0100): Marking server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0400): Marking port 3268 of duplicate server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_done] (0x2000): Old USN: 672384, New USN: 672395
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [dc=child1,dc=sssdad,dc=com]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=user1_dom3)(objectclass=user)(sAMAccountName=*)(objectSID=*))][dc=child1,dc=sssdad,dc=com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [be_run_online_cb] (0x0080): Going online. Running callbacks.
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_online_cb] (0x0400): The AD provider is online
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_online_cb] (0x0400): The AD provider is online
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [objectclass=domain][DC=sssdad,DC=com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 11
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication.
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [be_nsupdate_timer_schedule] (0x0200): Timer already scheduled
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_dyndns_update_send] (0x0400): Performing update
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_dyndns_update_send] (0x0200): Last periodic update ran recently or timerin progress, not scheduling another update
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_dyndns_nsupdate_done] (0x0040): DNS update finished
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_online_cb] (0x0400): The AD provider is online
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f7f150], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f7f150], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 1 results.
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_search_user_process] (0x4000): Retrieved total 1 users
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Save user
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Processing user user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x1000): Mapping user [user1_dom3@child1.sssdad.com] objectSID [S-1-5-21-3406858696-2348136156-2230084869-1380] to unix ID
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Original memberOf is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20140117112925.0Z] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Adding user principal [user1_dom3@CHILD1.SSSDAD.COM] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [512] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Storing info for user user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8f850
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8f910
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8f850 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8f910 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8f850 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sysdb_search_user_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8ea00
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8eb30
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8ea00 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8eb30 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8ea00 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sysdb_search_group_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f900b0
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f90170
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f900b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f90170 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f900b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sysdb_search_user_by_uid] (0x0400): No such entry
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f922d0
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f92400
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f922d0 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f92400 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f922d0 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f83420
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f9a7b0
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f83420 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f9a7b0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f83420 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f9b260
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f9ce20
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f9b260 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f9ce20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f9b260 "ltdb_callback"
>
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_save_users] (0x4000): User 0 processed!
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_users_done] (0x4000): Saving 1 Users - Done
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[(nil)], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f7e2d0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [DC=sssdad,DC=com].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f7e2d0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [ad_master_domain_next_done] (0x0400): Found SID [S-1-5-21-2153326666-2176343378-3404031434].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=sssdad.com)(NtVer=\14\00\00\00))][].
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 12
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f53e20], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:42 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f53e20], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netlogon]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f53e20], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ad_master_domain_netlogon_done] (0x0400): Found flat name [SSSDAD].
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=trustedDomain)(trustType=2)(!(msDS-TrustForestTrustInfo=*)))][DC=sssdad,DC=com].
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flatName]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustPartner]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [securityIdentifier]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustType]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustAttributes]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 13
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=sssdad_tree.com,CN=System,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [securityIdentifier]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustPartner]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustType]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustAttributes]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [flatName]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=child1.sssdad.com,CN=System,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [securityIdentifier]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustPartner]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustType]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [trustAttributes]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [flatName]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[0x7ff269f717a0], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f5c240
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f7d210
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f5c240 "ltdb_callback"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f7d210 "ltdb_timeout"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f5c240 "ltdb_callback"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f7ee40
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f7d590
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f7ee40 "ltdb_callback"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f7d590 "ltdb_timeout"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f7ee40 "ltdb_callback"
>
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [ad_subdomains_get_slave_domain_done] (0x1000): There are no changes
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[(nil)], ldap[0x7ff269f3a970]
>(Fri Jan 17 06:39:43 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:45 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:39:45 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:45 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f3b160
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [3][1][name=user1_dom3]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [be_req_set_domain] (0x0400): Changing request domain from [sssdad.com] to [child1.sssdad.com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f529d0
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f5c3b0
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f529d0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f5c3b0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f529d0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=child1,dc=sssdad,dc=com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=user1_dom3)(objectclass=user)(objectSID=*))][dc=child1,dc=sssdad,dc=com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f7f150], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[0x7ff269f7f150], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_user] (0x4000): Storing the user
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Save user
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Processing user user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x1000): Mapping user [user1_dom3@child1.sssdad.com] objectSID [S-1-5-21-3406858696-2348136156-2230084869-1380] to unix ID
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Original memberOf is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20140117112925.0Z] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Adding user principal [user1_dom3@CHILD1.SSSDAD.COM] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [512] to attributes of [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_save_user] (0x0400): Storing info for user user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8f4f0
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8f5b0
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8f4f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8f5b0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8f4f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8eb40
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8ec00
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8eb40 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8ec00 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8eb40 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [user1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f94e60
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f94f20
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f94f20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [user1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f94e60
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f94f20
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f94f20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [user1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f94e60
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f94f20
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f94f20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [user1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f94e60
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f94f20
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f94f20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f94e60 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_user] (0x4000): Commit change
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8e9f0
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8eb20
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8e9f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8eb20 "ltdb_timeout"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8e9f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): beginning to connect
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'child1.sssdad.com'
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'neutral'
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain child1.sssdad.com
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'child1.sssdad.com'
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.child1.sssdad.com'
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[(nil)], ldap[0x7ff269f724d0]
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:46 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing...
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [ad_get_dc_servers_done] (0x0400): Found 1 domain controllers in domain child1.sssdad.com
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [sdap_connect_host_send] (0x0400): Resolving host longhaul.child1.sssdad.com
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_is_address] (0x4000): [longhaul.child1.sssdad.com] does not look like an IP address
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'longhaul.child1.sssdad.com' in files
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'longhaul.child1.sssdad.com' in files
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'longhaul.child1.sssdad.com' in DNS
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:47 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:48 2014) [sssd[be[sssdad.com]]] [check_fd_timeouts] (0x4000): Checking for DNS timeouts
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [check_fd_timeouts] (0x4000): Checking for DNS timeouts
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_done] (0x0040): querying hosts database failed [5]: Input/output error
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [sdap_connect_host_resolv_done] (0x0040): Failed to resolve host longhaul.child1.sssdad.com: Timeout while contacting DNS servers
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [ad_get_client_site_connect_done] (0x0080): Unable to connect to domain controller [longhaul.child1.sssdad.com:389]
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_site_done] (0x0400): About to discover primary and backup servers
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [fo_discover_servers_send] (0x0400): Looking up primary servers
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'child1.sssdad.com'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.child1.sssdad.com'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing...
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [fo_discover_servers_primary_done] (0x0400): No backup domain specified
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [ad_srv_plugin_servers_done] (0x0400): Got 1 primary and 0 backup servers
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [fo_add_server_to_list] (0x0400): Inserted primary server 'longhaul.child1.sssdad.com:389' to service 'child1.sssdad.com'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'child1.sssdad.com' as 'resolved'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'longhaul.child1.sssdad.com' is 'name not resolved'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_is_address] (0x4000): [longhaul.child1.sssdad.com] does not look like an IP address
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'longhaul.child1.sssdad.com' in files
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [set_server_common_status] (0x0100): Marking server 'longhaul.child1.sssdad.com' as 'resolving name'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'longhaul.child1.sssdad.com' in files
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'longhaul.child1.sssdad.com' in DNS
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [set_server_common_status] (0x0100): Marking server 'longhaul.child1.sssdad.com' as 'name resolved'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x0200): Found address for server longhaul.child1.sssdad.com: [10.65.206.54] TTL 3600
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://longhaul.child1.sssdad.com'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://longhaul.child1.sssdad.com'
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x4000): Using file descriptor [24] for LDAP connection.
>(Fri Jan 17 06:39:49 2014) [sssd[be[sssdad.com]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://longhaul.child1.sssdad.com:389/??base] with fd [24].
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8f460], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8f460], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [currentTime]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [subschemaSubentry]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dsServiceName]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [schemaNamingContext]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [rootDomainNamingContext]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPPolicies]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [highestCommittedUSN]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dnsHostName]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ldapServiceName]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverName]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedCapabilities]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isSynchronized]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isGlobalCatalogReady]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainFunctionality]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [forestFunctionality]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainControllerFunctionality]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8f460], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_done] (0x2000): Got rootdse
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 264785 (int: 264785)
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [4]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_kinit_send] (0x0400): Attempting kinit (default, AMD-PIKE-05$, SSSDAD.COM, 86400)
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service child1.sssdad.com
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'child1.sssdad.com'
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'longhaul.child1.sssdad.com' is 'name resolved'
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'longhaul.child1.sssdad.com' is 'name resolved'
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x0200): Found address for server longhaul.child1.sssdad.com: [10.65.206.54] TTL 3600
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 38
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [897]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [897]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[(nil)], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [write_pipe_handler] (0x0400): All data has been sent!
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x1000): Waiting for child [897].
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x0100): child [897] finished successfully.
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_SSSDAD.COM], expired on [1389994790]
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1389959690
>(Fri Jan 17 06:39:50 2014) [sssd[be[sssdad.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: AMD-PIKE-05$
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'longhaul.child1.sssdad.com' as 'working'
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [set_server_common_status] (0x0100): Marking server 'longhaul.child1.sssdad.com' as 'working'
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing LDAP with LDAP
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'longhaul.child1.sssdad.com' as 'working'
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups]
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
>(Fri Jan 17 06:39:54 2014) [sssd[be[sssdad.com]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f96530], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [tokenGroups]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f96530], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing membership SID [S-1-5-32-545]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x0080): Domain not found for SID S-1-5-32-545
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing membership SID [S-1-5-21-3406858696-2348136156-2230084869-513]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f937a0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f95590
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f937a0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f95590 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f937a0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_entry_by_sid_str] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x0400): Missing SID S-1-5-21-3406858696-2348136156-2230084869-513 will be downloaded
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing membership SID [S-1-5-21-3406858696-2348136156-2230084869-1383]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f95320
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f99a10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f95320 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f99a10 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f95320 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_entry_by_sid_str] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_initgr_posix_tg_done] (0x0400): Missing SID S-1-5-21-3406858696-2348136156-2230084869-1383 will be downloaded
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f90220
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f907e0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f90220 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f907e0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f90220 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [user1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [dc=child1,dc=sssdad,dc=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectSID=S-1-5-21-3406858696-2348136156-2230084869-513)(objectclass=group)(name=*))][dc=child1,dc=sssdad,dc=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [groupType]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f94570], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f94570], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=Domain Users,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [groupType]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f94570], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f94570], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_has_deref_support] (0x0400): The server supports deref method ASQ
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x4000): AD group has type flags 0x80000002.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x4000): The group's gid was missing
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x2000): Marking group as non-posix and setting GID=0!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_entry] (0x4000): Inserting [CN=Domain Users,CN=Users,DC=child1,DC=sssdad,DC=com] into hash table [groups]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_process_send] (0x2000): About to process group [CN=Domain Users,CN=Users,DC=child1,DC=sssdad,DC=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_process_send] (0x2000): Looking up 0/0 members of group [CN=Domain Users,CN=Users,DC=child1,DC=sssdad,DC=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_recv] (0x0400): 0 users found in the hash table
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_recv] (0x0400): 1 groups found in the hash table
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object Domain Users@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x0400): Processing group Domain Users@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x4000): AD group [Domain Users@child1.sssdad.com] has type flags 0x80000002.(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x1000): Mapping group [Domain Users@child1.sssdad.com] objectSID [S-1-5-21-3406858696-2348136156-2230084869-513] to unix ID
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [CN=Domain Users,CN=Users,DC=child1,DC=sssdad,DC=com] to attributes of [Domain Users@child1.sssdad.com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20130821104743.0Z] to attributes of [Domain Users@child1.sssdad.com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_ghost_members] (0x0400): The group has 0 members
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_ghost_members] (0x0400): Group has 0 members
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x0400): Storing info for group Domain Users@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f96810
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f96940
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f96810 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f96940 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f96810 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_group_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f97d40
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f97e00
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f97d40 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f97e00 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f97d40 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_user_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fa61f0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f93c80
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fa61f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f93c80 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fa61f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_group_by_gid] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f9bc10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f97b90
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f9bc10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f97b90 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f9bc10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f98810
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f96880
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f98810 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fa7660
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f98dd0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f96880 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f98810 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fa7660 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f98dd0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fa7660 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_groups] (0x4000): Group 0 processed!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object Domain Users@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_grpmem] (0x0400): Processing group Domain Users@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_users] (0x2000): Search users with filter: (&(objectclass=user)(gidNumber=1290800513))
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f97e10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f99170
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f97e10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f99170 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f97e10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_users] (0x2000): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_grpmem] (0x0400): No members for group [Domain Users@child1.sssdad.com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f99170
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f97e10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f99170 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f97e10 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f99170 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fb1a10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f97b90
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fb1a10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f97b90 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fb1a10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_groups] (0x4000): Group 0 members processed!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [dc=child1,dc=sssdad,dc=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectSID=S-1-5-21-3406858696-2348136156-2230084869-1383)(objectclass=group)(name=*))][dc=child1,dc=sssdad,dc=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [groupType]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 7
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8eef0], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8eef0], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_entry] (0x4000): OriginalDN: [CN=group1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [member]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [groupType]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8eef0], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[0x7ff269f8eef0], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_has_deref_support] (0x0400): The server supports deref method ASQ
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x4000): AD group has type flags 0x80000002.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x4000): The group's gid was missing
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_group] (0x2000): Marking group as non-posix and setting GID=0!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_hash_entry] (0x4000): Inserting [CN=group1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com] into hash table [groups]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_process_send] (0x2000): About to process group [CN=group1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_users] (0x2000): Search users with filter: (&(objectclass=user)(originalDN=CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com))
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f9a290
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f9a3c0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f9a290 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f9a3c0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f9a290 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_split_members] (0x4000): [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com] found in cache, skipping
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_process_send] (0x2000): Looking up 0/1 members of group [CN=group1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_recv] (0x0400): 0 users found in the hash table
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_nested_group_recv] (0x0400): 1 groups found in the hash table
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object group1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x0400): Processing group group1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x4000): AD group [group1_dom3@child1.sssdad.com] has type flags 0x80000002.(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x1000): Mapping group [group1_dom3@child1.sssdad.com] objectSID [S-1-5-21-3406858696-2348136156-2230084869-1383] to unix ID
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [CN=group1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com] to attributes of [group1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20140117112214.0Z] to attributes of [group1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_ghost_members] (0x0400): The group has 1 members
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_ghost_members] (0x0400): Group has 1 members
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_group] (0x0400): Storing info for group group1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f9a1b0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f9a2e0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f9a1b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f9a2e0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f9a1b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_group_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f982e0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f983a0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f982e0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f983a0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f982e0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_user_by_name] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f97bc0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f98590
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f97bc0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f98590 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f97bc0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_group_by_gid] (0x0400): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f98f30
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f98ff0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f98f30 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f98ff0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f98f30 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f981f0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f982b0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f981f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f98d10
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269fa77b0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f982b0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f981f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f98d10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269fa77b0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f98d10 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_groups] (0x4000): Group 0 processed!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_primary_name] (0x0400): Processing object group1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_grpmem] (0x0400): Processing group group1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_users] (0x2000): Search users with filter: (&(objectclass=user)(gidNumber=1290801383))
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8e540
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269fb1fc0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8e540 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269fb1fc0 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8e540 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sysdb_search_users] (0x2000): No such entry
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_grpmem] (0x0400): Adding member users to group [group1_dom3@child1.sssdad.com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_find_entry_by_origDN] (0x4000): Searching cache for [CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com].
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f8e540
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269fb0b30
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f8e540 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269fb0b30 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f8e540 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_fill_memberships] (0x1000):     member #0 (CN=user1_dom3,CN=Users,DC=child1,DC=sssdad,DC=com): [name=user1_dom3@child1.sssdad.com,cn=users,cn=child1.sssdad.com,cn=sysdb]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fa77b0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f8e540
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fa77b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f8e540 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fa77b0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f98620
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f9bb60
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f98620 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fb1bd0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f98990
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f9bb60 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f98620 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fb1bd0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fb4d20
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f98e80
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f98990 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fb1bd0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fb4d20 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269fb5cc0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269fb5d80
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f98e80 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fb4d20 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269fb5cc0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f981f0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269fb4c70
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269fb5d80 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269fb5cc0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f981f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269fb4c70 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f981f0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_save_groups] (0x4000): Group 0 members processed!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_get_initgr_done] (0x1000): Mapping primary group to unix ID
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[(nil)], ldap[0x7ff269f8e7a0]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f3b160
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [be_req_set_domain] (0x0400): Changing request domain from [sssdad.com] to [child1.sssdad.com]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [be_pam_handler] (0x0100): Got request with the following data
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): domain: child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): user: user1_dom3@child1.sssdad.com
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): service: sshd
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): tty: ssh
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): ruser: 
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): rhost: localhost
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): authtok type: 1
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): newauthtok type: 0
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): priv: 1
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [pam_print_data] (0x0100): cli_pid: 894
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [krb5_pam_handler] (0x1000): Wait queue of user [user1_dom3@child1.sssdad.com] is empty, running request immediately.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f41fd0
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f52550
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f41fd0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f52550 "ltdb_timeout"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f41fd0 "ltdb_callback"
>
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [krb5_auth_send] (0x0100): Home directory for user [user1_dom3@child1.sssdad.com] not known.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [krb5_auth_send] (0x0100): No ccache file for user [user1_dom3@child1.sssdad.com] found.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [krb5_auth_send] (0x4000): Ccache_file is [not set] and is not active and TGT is not valid.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [be_resolve_server_process] (0x0200): Found address for server pluto.sssdad.com: [10.65.206.100] TTL 3600
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://pluto.sssdad.com'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://pluto.sssdad.com'
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [krb5_auth_prepare_ccache_name] (0x4000): Recreating  ccache file.
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [898]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [898]
>(Fri Jan 17 06:39:55 2014) [sssd[be[sssdad.com]]] [write_pipe_handler] (0x0400): All data has been sent!
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [krb5_child_timeout] (0x4000): timeout for child [898] reached.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [krb5_auth_done] (0x0020): child timed out!
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'pluto.sssdad.com' as 'not working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing LDAP with LDAP
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'pluto.sssdad.com' as 'not working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'pluto.sssdad.com' is 'not working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [get_server_status] (0x1000): Status of server 'pluto.sssdad.com' is 'working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'pluto.sssdad.com' is 'not working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_resolve_service_send] (0x0020): No available servers for service 'AD'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [be_resolve_server_done] (0x1000): Server resolution failed: 5
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [be_mark_offline] (0x2000): Going offline!
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [be_run_offline_cb] (0x0080): Going offline. Running callbacks.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [krb5_auth_prepare_ccache_name] (0x4000): Recreating  ccache file.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [krb5_auth_resolve_done] (0x4000): Preparing for offline operation.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [899]
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [899]
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x1000): Waiting for child [899].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [become_user] (0x0200): (Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x0020): Trying to become user [1290801380][1290801380].
>waitpid did not found a child with changed status.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x1000): Waiting for child [898].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x0020): child [898] was terminated by signal [9].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [write_pipe_handler] (0x0400): All data has been sent!
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x1000): Waiting for child [899].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [child_sig_handler] (0x0100): child [899] finished successfully.
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [parse_krb5_child_response] (0x1000): child response [0][3][41].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [set_server_common_status] (0x0100): Marking server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ad_user_data_cmp] (0x1000): Comparing LDAP with LDAP
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'pluto.sssdad.com' as 'working'
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [switch_creds] (0x0200): Switch user to [1290801380][1290801380].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [sss_krb5_check_ccache_princ] (0x2000): Searching for [user1_dom3@CHILD1.SSSDAD.COM] in cache of type [KEYRING]
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [switch_creds] (0x0200): Switch user to [0][0].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:1290801380] for user [user1_dom3@child1.sssdad.com].
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f519f0
>
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f7bbe0
>
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f519f0 "ltdb_callback"
>
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f7bbe0 "ltdb_timeout"
>
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f519f0 "ltdb_callback"
>
>(Fri Jan 17 06:40:01 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ff269f7ecd0
>
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ff269f519f0
>
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Running timer event 0x7ff269f7ecd0 "ltdb_callback"
>
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Destroying timer event 0x7ff269f519f0 "ltdb_timeout"
>
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): Ending timer event 0x7ff269f7ecd0 "ltdb_callback"
>
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sysdb_cache_auth] (0x4000): Offline credentials expiration is [0] days.
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [check_failed_login_attempts] (0x4000): Failed login attempts [0], allowed failed login attempts [0], failed login delay [5].
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sysdb_cache_auth] (0x0100): Cached credentials not available.
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0)
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [check_wait_queue] (0x1000): Wait queue for user [user1_dom3@child1.sssdad.com] is empty.
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 6, <NULL>) [Success]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [be_pam_handler_callback] (0x0100): Sending result [6][child1.sssdad.com]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [be_pam_handler_callback] (0x0100): Sent result [6][child1.sssdad.com]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x7ff269f8f540], connected[1], ops[(nil)], ldap[0x7ff269f8e7a0], destructor_lock[0], release_memory[0]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [remove_krb5_info_files] (0x0200): Could not remove [/var/lib/sss/pubconf/kpasswdinfo.SSSDAD.COM], [2][No such file or directory]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x7ff269f71490], connected[1], ops[(nil)], ldap[0x7ff269f724d0], destructor_lock[0], release_memory[0]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x7ff269f41170], connected[1], ops[(nil)], ldap[0x7ff269f3a970], destructor_lock[0], release_memory[0]
>(Fri Jan 17 06:40:02 2014) [sssd[be[sssdad.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Jan 17 06:40:05 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:40:05 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:40:05 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Jan 17 06:40:15 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7ff269f0e640
>(Fri Jan 17 06:40:15 2014) [sssd[be[sssdad.com]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Jan 17 06:40:15 2014) [sssd[be[sssdad.com]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]

Actions: View

Attachments on bug 1054899: 851732