==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:56:48 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #287: New request 'User by name' (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #287: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #287: Setting name [myuser] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #287: Performing a single domain search (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #287: Search will check the cache and check the data provider (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #287: Using domain [splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #287: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #287: Looking up myuser@splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #287: Object found, but needs to be refreshed. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #100]: New request. Flags [0x0001]. (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain splat.acme.com and site VA (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'VA._sites.splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.VA._sites.splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got 2 servers (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_done] (0x0400): Found 2 domain controllers in domain VA._sites.splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_send] (0x0400): Resolving host VA-PROD-AD02.splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in DNS (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=splat.acme.com)(NtVer=\14\00\00\00))][]. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_timeout] (0x0080): Service resolving timeout reached (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain splat.acme.com and site VA (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'VA._sites.splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.VA._sites.splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got 2 servers (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_done] (0x0400): Found 2 domain controllers in domain VA._sites.splat.acme.com (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_send] (0x0400): Resolving host VA-PROD-AD02.splat.acme.com (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in DNS (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=splat.acme.com)(NtVer=\14\00\00\00))][]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_timeout] (0x0080): Service resolving timeout reached (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #100]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #100]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #100]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #100]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #287: Data Provider Error: 3, 1432158271, Subdomain is inactive (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #287: Due to an error we will return cached data (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #287: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #287: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #287: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #287: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: nobody (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #288: New request 'Initgroups by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #288: Parsing input name [nobody] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'nobody' matched without domain, user is nobody (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #288: Setting name [nobody] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #288: Performing a multi-domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #288: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #288: Using domain [ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #288: Preparing input data for domain [ipa.splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #288: Looking up nobody@ipa.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #288: Checking negative cache for [nobody@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #288: [nobody@ipa.splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object [nobody@ipa.splat.acme.com] was not found in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [ipa.splat.acme.com][0x3][BE_REQ_INITGROUPS][name=nobody@ipa.splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=nobody@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #101]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=nobody)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [nobody@ipa.splat.acme.com] found. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_entry_by_sid_str] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_object_attr] (0x0400): No such entry. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_get_real_name] (0x0040): Cannot find user [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_by_name] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_by_name] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #101]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #101]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #101]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::ipa.splat.acme.com:name=nobody@ipa.splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #101]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object [nobody@ipa.splat.acme.com] was not found in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_add_to_domain] (0x0400): CR #288: Adding [nobody@ipa.splat.acme.com] to negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/ipa.splat.acme.com/nobody@ipa.splat.acme.com] to negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #288: Finished: Not found (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com] ==> /var/log/sssd/sssd_ssh.log <== (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [ssh_protocol_parse_request] (0x0400): Requested domain [] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [ssh_cmd_get_user_pubkeys] (0x0400): Requesting SSH user public keys for [myuser@splat.acme.com] from [] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_send] (0x0400): CR #1: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_process_input] (0x0400): CR #1: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_set_name] (0x0400): CR #1: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_select_domains] (0x0400): CR #1: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_domains] (0x0400): CR #1: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_set_domain] (0x0400): CR #1: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_prepare_domain_data] (0x0400): CR #1: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #1: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #1: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_dp] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #102]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #102]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #102]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #102]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #102]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_ssh.log <== (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache_filter] (0x0400): CR #1: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_done] (0x0400): CR #1: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_create_and_add_result] (0x0400): CR #1: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_done] (0x0400): CR #1: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #289: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #289: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #289: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #289: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #289: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #289: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #289: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #289: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #289: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #103]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #103]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #103]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #103]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #103]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #289: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #289: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #289: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #289: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #290: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #290: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #290: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #290: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #290: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #290: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #290: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #290: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #290: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #104]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #104]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #104]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #104]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #104]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #290: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #290: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #290: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #290: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #291: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #291: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #291: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #291: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #291: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #291: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #291: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #291: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #291: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #105]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #105]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #105]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #105]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #105]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #291: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #291: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #291: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #291: Finished: Success ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:00 2019) [sssd[pam]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #1: New request 'Initgroups by name' (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #1: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #1: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #1: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #1: Search will bypass the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #1: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #1: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #1: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #106]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #106]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #106]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #106]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #106]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #1: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #1: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #1: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #1: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #107]: New request. Flags [0000]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [main] (0x0400): Will perform pre-auth (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_child_timeout] (0x0040): Timeout for child [11388] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0020): child timed out! (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #107]: Request handler finished [0]: Success (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #107]: Receiving request data. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #107]: Request removed. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [15 (Authentication service cannot retrieve user credentials)][splat.acme.com] (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [15]: Authentication service cannot retrieve user credentials. (Fri Feb 15 15:57:06 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 29 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0020): child [11388] was terminated by signal [9]. ==> /var/log/sssd/sssd_pac.log <== (Fri Feb 15 15:57:07 2019) [sssd[pac]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:07 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [389]. ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #2: New request 'Initgroups by name' (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #2: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #2: Setting name [myuser] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #2: Performing a single domain search (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #2: Search will bypass the cache and check the data provider (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #2: Using domain [splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #2: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #2: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #108]: New request. Flags [0x0001]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #108]: Request handler finished [0]: Success (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #108]: Receiving request data. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #108]: Finished. Success. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #108]: Request removed. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #2: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #2: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #2: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #2: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #2: Finished: Success (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #109]: New request. Flags [0000]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [unpack_buffer] (0x0100): cmd [241] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): Will perform offline auth (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [k5c_send_data] (0x0200): Received error code 1432158209 (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [11396] finished successfully. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #109]: Request handler finished [0]: Success (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #109]: Receiving request data. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #109]: Request removed. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Fri Feb 15 15:57:09 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 29 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected! ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #292: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #292: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #292: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #292: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #292: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #292: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #292: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #292: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #292: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #292: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #292: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #292: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #292: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #293: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #293: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #293: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #293: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #293: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #293: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #293: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #293: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #293: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #111]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #111]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #111]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #111]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #111]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #293: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #293: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #293: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #293: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #294: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #294: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #294: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #294: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #294: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #294: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #294: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #294: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #294: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #112]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #112]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #112]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #112]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #112]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #294: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #294: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #294: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #294: Finished: Success ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #3: New request 'Initgroups by name' (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #3: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #3: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #3: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #3: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #3: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #3: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #3: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #3: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #113]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #113]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #113]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #113]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #113]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #3: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #3: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #3: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #3: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #114]: New request. Flags [0000]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): Will perform pre-auth (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [k5c_send_data] (0x0200): Received error code 0 (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [11400] finished successfully. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [cache, ts_cache] attrs. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_cache_creds] (0x0080): Delayed authentication is only available for password authentication (single factor). (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #114]: Request handler finished [0]: Success (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #114]: Receiving request data. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #114]: Request removed. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Fri Feb 15 15:57:12 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 ^C [root@va-prod-ipa01 ~]# getent passwd myuser@splat.acme.com myuser@splat.acme.com:*:612329895:612329895:myuser:/home/splat.acme.com/myuser: [root@va-prod-ipa01 ~]# kinit myuser@splat.acme.com Password for myuser@splat.acme.com: [root@va-prod-ipa01 ~]#