Apologies, forgot to attach.
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐
On Friday, February 15, 2019 11:19 AM, D via FreeIPA-users
<freeipa-users(a)lists.fedorahosted.org> wrote:
> New logs are attached. They are from attempts to ssh into the IPA server as one of
the AD users.
>
> I think this is the problem now, but the full logs are attached in case I'm
mistaken.
>
> ==> /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.
Ok, the timeout is happening already during pre-auth setting the backend
into offline-mode. Maybe the keyring error is related to the offline
mode, although I do not see it in my setup when offline.
Have you tried the suggestion from the debug message and increased
krb5_auth_timeout in the [domain/....] section of sssd.conf? The default
is 6 (seconds), I would suggest to try 30 for a start. And please set
debug_level=9 in the [domain/...] section as well. I extra output might
help to identify where the delay is coming from.
bye,
Sumit
==> /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(a)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(a)splat.acme.com]
(Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)ipa.splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #288:
[nobody(a)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(a)ipa.splat.acme.com] in cache
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object
[nobody(a)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(a)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(a)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(a)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(a)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(a)ipa.splat.acme.com] in cache
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object
[nobody(a)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(a)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 [<ALL>]
(Fri Feb 15 15:57:00 2019) [sssd[ssh]] [ssh_cmd_get_user_pubkeys] (0x0400): Requesting
SSH user public keys for [myuser(a)splat.acme.com] from [<ALL>]
(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(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser(a)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(a)splat.acme.com
(Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3:
Checking negative cache for [myuser(a)splat.acme.com]
(Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3:
[myuser(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)splat.acme.com
myuser@splat.acme.com:*:612329895:612329895:myuser:/home/splat.acme.com/myuser:
[root@va-prod-ipa01 ~]# kinit myuser(a)splat.acme.com
Password for myuser(a)splat.acme.com:
[root@va-prod-ipa01 ~]#