On Fri, Nov 04, 2016 at 01:41:40PM +0200, Taras Drach wrote:
> Hello Sumit,
> I’ve tried to use this attr, but still no success
> 
> Also I found the solutions where sss_ssh_authorizedkeys replaced with custom 
> scripts for queuing ldap and get necessary attribute
> I think there is hardcoded “sshPublicKey" in sss_ssh_authorizedkeys. 

yes, sshPublicKey is hardcoded but originalADsshPublicKey should be
handled as well. I just found that there is a bug which prevents the ssh
responder to handle it as expected.

In general the attribute names in SSSD's cache are hardcoded. What is
configurable is which server side LDAP attributed is stored in a
specific cache attribute (all the ldap_user_* and ldap_group_*
attributes can be used for this.

ldap_user_extra_attrs is special to allow to stored arbitrary attributes
in the cache. But since the hardcoded cache attributes typically have
special use-cases they cannot be overridden, this is why you have seen
the error message with sshPublicKey. originalADsshPublicKey has some
special instal use-case as well, but currently it is not in the list of
attributes which is checked. Nevertheless there is the bug I mentioned
earlier which make the lookup fail as well.

The intended way to solve all this is to use "ldap_user_ssh_public_key =
altSecurityIdentities" which I expect to work in the case where the
client is joined directly to an AD domain.  With IPA and trust this is
unfortunately a bit different. The ldap_user_ssh_public_key will only
change the attribute name for the IPA domain but not for the trusted AD
domain because options are not inherited by default. Additionally
changing the attribute name for the IPA domain will prevent SSSD from
reading the SSH keys stored in the IPA server. The proper solution would
be domain specific configuration options which is tracked by
https://fedorahosted.org/sssd/ticket/2599 .

Nevertheless I try to fix the bug I mentioned earlier and will prepare a
test-build with a fix at the beginning of the next week.

HTH

bye,
Sumit


> Is there any other way to create some kind of mapping in IPA for this 
> attribute? 
> I see that AD attribute requested and printed its content in the log, but 
> still sss_ssh_authorizedkeys did not print this key to stdout
> 
> Full trace of 
> sss_ssh_authorizedkeys -d test.loc rr
> ==
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [be_get_account_info] 
> (0x0200): Got request for [0x1][1][name=rr]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [be_req_set_domain] 
> (0x0400): Changing request domain from [ipa.test.loc] to [test.loc]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_step] 
> (0x4000): reusing cached connection
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_step] 
> (0x4000): reusing cached connection
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view 
> [Default Trust View] with filter [(&(objectClass=ipaUserOverride)(uid=rr))].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.4
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [(&(objectClass=ipaUserOverride)(uid=rr))][cn=Default Trust 
> View,cn=views,cn=accounts,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 6 timeout 60
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de1415190], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 6 finished
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_get_ad_override_done] (0x4000): No override found with filter 
> [(&(objectClass=ipaUserOverride)(uid=rr))].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_destroy] 
> (0x4000): releasing operation connection
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_step] 
> (0x4000): beginning to connect
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_resolve_service_send] 
> (0x0100): Trying to resolve service 'test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [get_server_status] 
> (0x1000): Status of server 'dc01.test.loc' is 'working'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [get_port_status] 
> (0x1000): Port status of port 389 for server 'dc01.test.loc' is 'working'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 
> seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolve_srv_send] 
> (0x0200): The status of SRV lookup is expired
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [collapse_srv_lookup] 
> (0x0100): Need to refresh SRV lookup for domain 
> Default-First-Site-Name._sites.test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_srv_plugin_send] 
> (0x0400): About to find domain controllers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_get_dc_servers_send] 
> (0x0400): Looking up domain controllers in domain test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. 
> Will use DNS discovery domain 'test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_send] 
> (0x0100): Trying to resolve SRV record of '_ldap._tcp.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[(nil)], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: ldap_result found nothing!
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_done] 
> (0x1000): Using TTL [600]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [request_watch_destructor] (0x0400): Deleting request watch
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got answer. Processing...
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got 1 servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_get_dc_servers_done] 
> (0x0400): Found 1 domain controllers in domain test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_srv_plugin_dcs_done] 
> (0x0400): About to locate suitable site
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_connect_host_send] 
> (0x0400): Resolving host dc01.test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_is_address] 
> (0x4000): [dc01.test.loc] does not look like an IP address
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 
> 'dc01.test.loc' in files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 
> 'dc01.test.loc' in files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_next] (0x0200): No more address families to retry
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying DNS
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 
> 'dc01.test.loc' in DNS
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [request_watch_destructor] (0x0400): Deleting request watch
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_connect_host_resolv_done] (0x0400): Connecting to 
> ldap://dc01.test.loc:389
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sss_ldap_init_send] 
> (0x4000): Using file descriptor [27] for LDAP connection.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sss_ldap_init_send] 
> (0x0400): Setting 6 seconds timeout for connecting
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to 
> [ldap://dc01.test.loc:389/??base] with fd [27].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_connect_host_done] 
> (0x0400): Successful connection to ldap://dc01.test.loc:389
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.148
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [(&(DnsDomain=test.loc)(NtVer=\14\00\00\00))][].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 1 timeout 6
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1417710], connected[1], ops[0x7f0de1411070], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [netlogon]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1417710], connected[1], ops[0x7f0de1411070], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 1 finished
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_handle_release] 
> (0x2000): Trace: sh[0x7f0de1417710], connected[1], ops[(nil)], 
> ldap[0x7f0de13fc080], destructor_lock[0], release_memory[0]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [remove_connection_callback] (0x4000): Successfully removed connection 
> callback.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_get_client_site_done] 
> (0x0400): Found site: Default-First-Site-Name
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_srv_plugin_site_done] 
> (0x0400): About to discover primary and backup servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [fo_discover_servers_send] (0x0400): Looking up primary servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. 
> Will use DNS discovery domain 'Default-First-Site-Name._sites.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_send] 
> (0x0100): Trying to resolve SRV record of 
> '_ldap._tcp.Default-First-Site-Name._sites.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_done] 
> (0x1000): Using TTL [600]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [request_watch_destructor] (0x0400): Deleting request watch
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got answer. Processing...
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got 1 servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [fo_discover_servers_primary_done] (0x0400): Looking up backup servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. 
> Will use DNS discovery domain 'test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_send] 
> (0x0100): Trying to resolve SRV record of '_ldap._tcp.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_getsrv_done] 
> (0x1000): Using TTL [600]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [request_watch_destructor] (0x0400): Deleting request watch
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got answer. Processing...
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_discover_srv_done] 
> (0x0400): Got 1 servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ad_srv_plugin_servers_done] (0x0400): Got 1 primary and 1 backup servers
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_add_server_to_list] 
> (0x0400): Inserted primary server 'dc01.test.loc:389' to service 'test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_user_data_cmp] 
> (0x1000): Comparing LDAP with LDAP
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_add_server_to_list] 
> (0x0400): Server 'dc01.test.loc:389' for service 'test.loc' is already present
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [set_srv_data_status] 
> (0x0100): Marking SRV lookup of service 'test.loc' as 'resolved'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [get_server_status] 
> (0x1000): Status of server 'dc01.test.loc' is 'name not resolved'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolv_is_address] 
> (0x4000): [dc01.test.loc] does not look like an IP address
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 
> 'dc01.test.loc' in files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [set_server_common_status] (0x0100): Marking server 'dc01.test.loc' as 
> 'resolving name'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 
> 'dc01.test.loc' in files
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_next] (0x0200): No more address families to retry
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_step] (0x2000): Querying DNS
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 
> 'dc01.test.loc' in DNS
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [request_watch_destructor] (0x0400): Deleting request watch
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [set_server_common_status] (0x0100): Marking server 'dc01.test.loc' as 'name 
> resolved'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [be_resolve_server_process] (0x1000): Saving the first resolved server
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [be_resolve_server_process] (0x0200): Found address for server dc01.test.loc: 
> [10.100.0.148] TTL 2108
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_resolve_callback] 
> (0x0100): Constructed uri 'ldap://dc01.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_resolve_callback] 
> (0x0100): Constructed GC uri 'ldap://dc01.test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sss_ldap_init_send] 
> (0x4000): Using file descriptor [27] for LDAP connection.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sss_ldap_init_send] 
> (0x0400): Setting 6 seconds timeout for connecting
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to 
> [ldap://dc01.test.loc:389/??base] with fd [27].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_rootdse_send] 
> (0x4000): Getting rootdse
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.148
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [(objectclass=*)][].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: 
> [supportedSASLMechanisms]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: 
> [domainControllerFunctionality]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 1 timeout 6
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13fc730], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [currentTime]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [subschemaSubentry]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [dsServiceName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [namingContexts]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [defaultNamingContext]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [schemaNamingContext]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [configurationNamingContext]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [rootDomainNamingContext]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedControl]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedLDAPVersion]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedLDAPPolicies]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [highestCommittedUSN]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedSASLMechanisms]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [dnsHostName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [ldapServiceName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [serverName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedCapabilities]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [isSynchronized]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [isGlobalCatalogReady]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [supportedExtension]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [domainFunctionality]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [forestFunctionality]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [domainControllerFunctionality]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13fc730], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 1 finished
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_rootdse_done] 
> (0x2000): Got rootdse
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_rootdse_done] 
> (0x2000): Skipping auto-detection of match rule
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 16849 (int: 16849)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level 
> to [6]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_kinit_send] 
> (0x0400): Attempting kinit (default, host/ipa42.ipa.test.loc, AWS.SLT.LOC, 
> 86400)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_kinit_next_kdc] 
> (0x1000): Resolving next KDC for service test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_resolve_service_send] 
> (0x0100): Trying to resolve service 'test.loc'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [get_server_status] 
> (0x1000): Status of server 'dc01.test.loc' is 'name resolved'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 
> seconds
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [resolve_srv_send] 
> (0x0200): The status of SRV lookup is resolved
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [get_server_status] 
> (0x1000): Status of server 'dc01.test.loc' is 'name resolved'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [be_resolve_server_process] (0x1000): Saving the first resolved server
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [be_resolve_server_process] (0x0200): Found address for server dc01.test.loc: 
> [10.100.0.148] TTL 2108
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_kinit_kdc_resolved] 
> (0x1000): KDC resolved, attempting to get TGT...
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [create_tgt_req_send_buffer] (0x0400): buffer size: 57
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [child_handler_setup] 
> (0x2000): Setting up signal handler up for pid [31250]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [child_handler_setup] 
> (0x2000): Signal handler set up for pid [31250]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [set_tgt_child_timeout] 
> (0x0400): Setting 6 seconds timeout for tgt child
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[(nil)], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: ldap_result found nothing!
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [write_pipe_handler] 
> (0x0400): All data has been sent!
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [child_sig_handler] 
> (0x1000): Waiting for child [31250].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [child_sig_handler] 
> (0x0100): child [31250] finished successfully.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [read_pipe_handler] 
> (0x0400): EOF received, client finished
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_tgt_recv] 
> (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_AWS.SLT.LOC], 
> expired on [1478344941]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_cli_auth_step] 
> (0x0100): expire timeout is 900
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_cli_auth_step] 
> (0x1000): the connection will expire at 1478259441
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sasl_bind_send] 
> (0x0100): Executing sasl bind mech: gssapi, user: host/ipa42.ipa.test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [_be_fo_set_port_status] 
> (0x8000): Setting status: PORT_WORKING. Called from: 
> src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2036
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_set_port_status] 
> (0x0100): Marking port 389 of server 'dc01.test.loc' as 'working'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [set_server_common_status] (0x0100): Marking server 'dc01.test.loc' as 
> 'working'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ad_user_data_cmp] 
> (0x1000): Comparing LDAP with LDAP
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [fo_set_port_status] 
> (0x0400): Marking port 389 of duplicate server 'dc01.test.loc' as 'working'
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_done] 
> (0x2000): Old USN: 16844, New USN: 16849
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_done] 
> (0x4000): notify connected to op #1
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_search_user_next_base] (0x0400): Searching for users with base 
> [dc=test,dc=loc]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.148
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [(&(sAMAccountName=rr)(objectclass=user)(sAMAccountName=*)(objectSID=*))][dc=test,dc=loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: 
> [altSecurityIdentities]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 5 timeout 6
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_done] 
> (0x4000): caching successful connection after 1 notifies
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [be_run_unconditional_online_cb] (0x0400): Running unconditional online 
> callbacks.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [CN=rr,CN=Users,DC=test,DC=loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectClass]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [whenChanged]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [uSNChanged]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [name]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectGUID]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [userAccountControl]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [primaryGroupID]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectSid]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [accountExpires]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [sAMAccountName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [userPrincipalName]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [altSecurityIdentities]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_add_references] (0x1000): Additional References: 
> ldap://ForestDnsZones.test.loc/DC=ForestDnsZones,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_add_references] (0x1000): Additional References: 
> ldap://DomainDnsZones.test.loc/DC=DomainDnsZones,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_add_references] (0x1000): Additional References: 
> ldap://test.loc/CN=Configuration,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 5 finished
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [generic_ext_search_handler] (0x4000): Request included referrals which were 
> ignored.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [generic_ext_search_handler] (0x4000):     Ref: 
> ldap://ForestDnsZones.test.loc/DC=ForestDnsZones,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [generic_ext_search_handler] (0x4000):     Ref: 
> ldap://DomainDnsZones.test.loc/DC=DomainDnsZones,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [generic_ext_search_handler] (0x4000):     Ref: 
> ldap://test.loc/CN=Configuration,DC=test,DC=loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_search_user_process] (0x0400): Search for users, returned 1 results.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_search_user_process] (0x4000): Retrieved total 1 users
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 0)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x0400): Save user
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_primary_name] 
> (0x0400): Processing object r...@test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x0400): Processing user r...@test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x1000): Mapping user [r...@test.loc] objectSID 
> [S-1-5-21-237804563-1161820721-801220523-1106] to unix ID
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x2000): Adding originalDN [CN=rr,CN=Users,DC=test,DC=loc] to attributes of 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x0400): Original memberOf is not available for [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp 
> [20161103142350.0Z] to attributes of [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x0400): Adding user principal [r...@slt.loc] to attributes of 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available 
> for [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): Adding adAccountExpires 
> [9223372036854775807] to attributes of [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [66048] to 
> attributes of [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available 
> for [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available 
> for [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for 
> [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_attrs_add_ldap_attr] (0x2000): Adding originalADsshPublicKey 
> [ssh-rsa\20AAAAB3NzaC1yc2EAAAADAQABAAABAQDQydFCKx/r5idp3U0EY0fMJdu0eHNuIc6xvZudQJm/mbf3TflLNH+mj/Jr7yQaPj0C6z7V8my+D0f6JK1cCntxfhLQto92xUZhhKoLHVO34f5DhC5etqZ4EtaD6j9QuXYc5U8GovHgzmdH+JSeIOSpSqFzTkFR6sSmhjypfCDPCP8JKHxwI9LJvfgCRv0qKJBjELhUpZYUW3Mrcpp+bJcX8Iuz0QPDkO2VdqIcwapC+h6AhdH+Sm6PjG8FplH6/5SDlQ2LOVTnY4xMuS48RXzgtJImN+o7syrxjPTQU5/PWXiIH/Hawa6n75kREv6B4AHtQKxqDoxhNdzQ1+xiLs4H\20u...@test.loc]
>  to attributes of [r...@test.loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sysdb_attrs_get_aliases] 
> (0x2000): Domain is case-insensitive; will add lowercased aliases
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_user] 
> (0x0400): Storing info for user r...@test.loc
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 1)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1434da0
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1434ed0
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1434da0 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1434ed0 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1434da0 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sysdb_search_by_name] 
> (0x0400): No such entry
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 2)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1445110
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1435ae0
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1445110 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1435ae0 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1445110 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sysdb_search_by_name] 
> (0x0400): No such entry
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de143b020
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de13f5b20
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de143b020 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de13f5b20 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de143b020 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sysdb_search_user_by_uid] (0x0400): No such entry
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 3)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1445690
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1444c50
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1445690 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1444c50 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1445690 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 3)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 3)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1440550
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1435c90
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1440550 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1435c90 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1440550 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 3)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1445d20
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de13f5b20
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1445d20 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de13f5b20 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1445d20 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 2)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 1)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_save_users] 
> (0x4000): User 0 processed!
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 0)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_get_users_done] 
> (0x4000): Saving 1 Users - Done
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_done] 
> (0x4000): releasing operation connection
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de13fa1b0
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de13fa2e0
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de13fa1b0 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de13fa2e0 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de13fa1b0 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [apply_subdomain_homedir] 
> (0x4000): Missing homedir of r...@test.loc.
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 0)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): start ldb 
> transaction (nesting: 1)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1419a10
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1435570
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1419a10 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1435570 "ltdb_timeout"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1419a10 "ltdb_callback"
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 1)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): commit 
> ldb transaction (nesting: 0)
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_step] 
> (0x4000): reusing cached connection
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view 
> [Default Trust View] with filter 
> [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-237804563-1161820721-801220523-1106))].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.4
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-237804563-1161820721-801220523-1106))][cn=Default
>  Trust View,cn=views,cn=accounts,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 7
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 7 timeout 60
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de1411070], connected[1], ops[(nil)], 
> ldap[0x7f0de13fc080]
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: ldap_result found nothing!
> (Fri Nov  4 11:22:21 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_subdom_reset_timeouts_cb] (0x4000): Resetting last_refreshed and 
> disabled_until.
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de1415190], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 7 finished
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [ipa_get_ad_override_done] (0x4000): No override found with filter 
> [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-237804563-1161820721-801220523-1106))].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_destroy] 
> (0x4000): releasing operation connection
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de13fa4e0
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1419d50
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de13fa4e0 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1419d50 "ltdb_timeout"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de13fa4e0 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_connect_step] 
> (0x4000): reusing cached connection
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_print_server] 
> (0x2000): Searching 10.100.0.4
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
> [objectClass=ipaexternalgroup][dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 8
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_op_add] (0x2000): 
> New operation 8 timeout 60
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: ldap_result found nothing!
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [cn=ab,cn=groups,cn=compat,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [gidNumber]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [ipaAnchorUUID]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectClass]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [cn]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [cn=Default SMB 
> Group,cn=groups,cn=compat,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [gidNumber]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [ipaAnchorUUID]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectClass]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [cn]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [cn=editors,cn=groups,cn=compat,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [gidNumber]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [ipaAnchorUUID]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectClass]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [cn]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_entry] 
> (0x1000): OriginalDN: [cn=admins,cn=groups,cn=compat,dc=ipa,dc=test,dc=loc].
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [gidNumber]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [ipaAnchorUUID]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [memberUid]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [objectClass]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_parse_range] 
> (0x2000): No sub-attributes for [cn]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[0x7f0de13eb710], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_message] 
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg 
> set
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_op_destructor] 
> (0x2000): Operation 8 finished
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ipa_get_ext_groups_done] 
> (0x0400): [4] external groups found.
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1444a10
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de1444b40
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1444a10 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de1444b40 "ltdb_timeout"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1444a10 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_callback": 0x7f0de1444a10
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Added 
> timed event "ltdb_timeout": 0x7f0de14457f0
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Running 
> timer event 0x7f0de1444a10 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): 
> Destroying timer event 0x7f0de14457f0 "ltdb_timeout"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ldb] (0x4000): Ending 
> timer event 0x7f0de1444a10 "ltdb_callback"
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [find_ipa_ext_memberships] (0x4000): SID 
> [S-1-5-21-237804563-1161820721-801220523-1106] not found in ext group hash.
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] 
> [find_ipa_ext_memberships] (0x0400): No external groupmemberships found.
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [ipa_add_ext_groups_step] 
> (0x4000): No external groups memberships found.
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_destroy] 
> (0x4000): releasing operation connection
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_id_op_destroy] 
> (0x4000): releasing operation connection
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [acctinfo_callback] 
> (0x0100): Request processed. Returned 0,0,Success (Success)
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: sh[0x7f0de13ebfe0], connected[1], ops[(nil)], 
> ldap[0x7f0de13e8be0]
> (Fri Nov  4 11:22:22 2016) [sssd[be[ipa.test.loc]]] [sdap_process_result] 
> (0x2000): Trace: ldap_result found nothing!
> 
> 
> > On Nov 4, 2016, at 12:51 PM, Sumit Bose <sb...@redhat.com> wrote:
> > 
> > On Thu, Nov 03, 2016 at 05:23:06PM +0200, Taras Drach wrote:
> >> Thank for reply,
> >> 
> >> Unfortunately sssd won’t start with this configuration
> >> 
> >> Here is part of log
> >> 
> >> (Thu Nov  3 15:16:40 2016) [sssd[be[ipa.test.loc]]] [sdap_extend_map] 
> >> (0x0200): 1 extra attributes
> >> (Thu Nov  3 15:16:40 2016) [sssd[be[ipa.test.loc]]] [sdap_extend_map] 
> >> (0x0010): Attribute sshPublicKey (altSecurityIdentities in LDAP) is 
> >> already used by SSSD, please choose a different cache name
> > 
> > Can you check if 
> > 
> >    ldap_user_extra_attrs = originalADsshPublicKey:altSecurityIdentities
> > 
> > works any better?
> > 
> > bye,
> > Sumit
> > 
> >> (Thu Nov  3 15:16:40 2016) [sssd[be[ipa.test.loc]]] [load_backend_module] 
> >> (0x0010): Error (1432158241) in module (ipa) initialization 
> >> (sssm_ipa_id_init)!
> >> (Thu Nov  3 15:16:40 2016) [sssd[be[ipa.test.loc]]] [be_process_init] 
> >> (0x0010): fatal error initializing data providers
> >> (Thu Nov  3 15:16:40 2016) [sssd[be[ipa.test.loc]]] [sbus_remove_watch] 
> >> (0x2000): 0x7f8183df2640/0x7f8183df2420
> >> 
> >> Config changes:
> >> 
> >>   ldap_user_extra_attrs = sshPublicKey:altSecurityIdentities
> >> #   ldap_user_extra_attrs = altSecurityIdentities:altSecurityIdentities
> >>   ldap_user_ssh_public_key = altSecurityIdentities
> >>   ldap_id_mapping = False
> >> 
> >>> On Nov 3, 2016, at 5:05 PM, Sumit Bose <sb...@redhat.com> wrote:
> >>> 
> >>> sshPublicKey:
> >> 
> > 
> > 
> 

-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to