==> /var/log/sssd/sssd_ssh.log <== (Mon Apr 8 13:57:30 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. (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [accept_fd_handler] (0x0400): Client connected! (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [ssh_protocol_parse_request] (0x0400): Requested domain [] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [ssh_cmd_get_host_pubkeys] (0x0400): Requesting SSH host public keys for [va-prod-ipa01.ipa.splat.acme.com] from [] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_send] (0x0400): CR #12: New request 'Host by name' (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_process_input] (0x0400): CR #12: Parsing input name [va-prod-ipa01.ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'va-prod-ipa01.ipa.splat.acme.com' matched without domain, user is va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_set_name] (0x0400): CR #12: Setting name [va-prod-ipa01.ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_select_domains] (0x0400): CR #12: Performing a multi-domain search (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_domains] (0x0400): CR #12: Search will bypass the cache and check the data provider (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_set_domain] (0x0400): CR #12: Using domain [ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #12: Looking up va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_dp] (0x0400): CR #12: Looking up [va-prod-ipa01.ipa.splat.acme.com] in data provider (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fb9a7bb78e0:va-prod-ipa01.ipa.splat.acme.com:va-prod-ipa01.ipa.splat.acme.com@ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_dp_get_ssh_host_msg] (0x0400): Creating SSH host request for [ipa.splat.acme.com][0][va-prod-ipa01.ipa.splat.acme.com][va-prod-ipa01.ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fb9a7bb78e0:va-prod-ipa01.ipa.splat.acme.com:va-prod-ipa01.ipa.splat.acme.com@ipa.splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [HostID #327]: New request. Flags [0000]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=va-prod-ipa01.ipa.splat.acme.com))][cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_store_ssh_host] (0x0400): Storing host va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [HostID #327]: Request handler finished [0]: Success (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [HostID #327]: Receiving request data. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [HostID #327]: Finished. Success. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [7:7:0000:va-prod-ipa01.ipa.splat.acme.com:va-prod-ipa01.ipa.splat.acme.com] from reply table (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [HostID #327]: Request removed. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_ssh.log <== (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #12: Looking up [va-prod-ipa01.ipa.splat.acme.com] in cache (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_ncache_filter] (0x0400): CR #12: This request type does not support filtering result by negative cache (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_search_done] (0x0400): CR #12: Returning updated object [va-prod-ipa01.ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_create_and_add_result] (0x0400): CR #12: Found 1 entries in domain ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fb9a7bb78e0:va-prod-ipa01.ipa.splat.acme.com:va-prod-ipa01.ipa.splat.acme.com@ipa.splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [cache_req_done] (0x0400): CR #12: Finished: Success (Mon Apr 8 13:57:30 2019) [sssd[ssh]] [sysdb_update_ssh_known_host_expire] (0x0400): Updating known_hosts expire time of host va-prod-ipa01.ipa.splat.acme.com ==> /var/log/sssd/sssd_pam.log <== (Mon Apr 8 13:57:30 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. (Mon Apr 8 13:57:30 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #40: New request 'Initgroups by name' (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #40: Parsing input name [myuser@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #40: Setting name [myuser] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #40: Performing a single domain search (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #40: Search will bypass the cache and check the data provider (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #40: Using domain [splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #40: Preparing input data for domain [splat.acme.com] rules (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #40: Looking up myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #40: Checking negative cache for [myuser@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #40: [myuser@splat.acme.com] is not present in negative cache (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #40: Looking up [myuser@splat.acme.com] in data provider (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f07bf7ae550:3:myuser@splat.acme.com@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f07bf7ae550:3:myuser@splat.acme.com@splat.acme.com] ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #328]: New request. Flags [0x0001]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Apr 8 13:57:30 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=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=splat,dc=acme,dc=com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=myuser)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=splat,dc=acme,dc=com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=myuser)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_save_user] (0x0400): Save user (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_primary_name] (0x0400): Processing object myuser (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_save_user] (0x0400): Processing user myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [myuser@splat.acme.com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_save_user] (0x0400): Adding user principal [myuser@SPLAT.acme.com] to attributes of [myuser@splat.acme.com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_save_user] (0x0400): Storing info for user myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [cache, ts_cache] attrs. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=myuser,CN=Users,DC=splat,DC=acme,DC=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-544][BUILTIN\Administrators] which is currently not handled by SSSD. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-568][BUILTIN\IIS_IUSRS] which is currently not handled by SSSD. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-555][BUILTIN\Remote Desktop Users] which is currently not handled by SSSD. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-545][BUILTIN\Users] which is currently not handled by SSSD. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-580][BUILTIN\Remote Management Users] which is currently not handled by SSSD. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_group_by_gid] (0x0400): No such entry (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [dc=splat,dc=acme,dc=com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(gidNumber=611030303)(objectClass=group)(sAMAccountName=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 0 results. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [cache, ts_cache] attrs. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-1106047975-2404993722-2847199283-1117))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-1106047975-2404993722-2847199283-513))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-1106047975-2404993722-2847199283-1103))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-1106047975-2404993722-2847199283-1147))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_search_bases_ex_next_base] (0x0400): Issuing LDAP lookup with base [cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [objectClass=ipaexternalgroup][cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_search_bases_ex_done] (0x0400): Receiving data from base [cn=accounts,dc=ipa,dc=splat,dc=acme,dc=com] (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_get_ext_groups_done] (0x0400): [1] external groups found. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [cache, ts_cache] attrs. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #328]: Request handler finished [0]: Success (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #328]: Receiving request data. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [ts_cache] attrs. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #328]: Finished. Success. (Mon Apr 8 13:57:30 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 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #328]: Request removed. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #40: Looking up [myuser@splat.acme.com] in cache (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #40: This request type does not support filtering result by negative cache (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #40: Returning updated object [myuser@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #40: Found 15 entries in domain splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f07bf7ae550:3:myuser@splat.acme.com@splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #40: Finished: Success (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #329]: New request. Flags [0000]. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Apr 8 13:57:30 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 (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log-20190405 <== (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [main] (0x0400): krb5_child started. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [unpack_buffer] (0x0100): cmd [249] uid [611030303] gid [611030303] validate [true] enterprise principal [false] offline [false] UPN [myuser@SPLAT.acme.com] (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:611030303] old_ccname: [KEYRING:persistent:611030303] keytab: [/etc/krb5.keytab] (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/va-prod-ipa01.ipa.splat.acme.com@IPA.SPLAT.acme.com] (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [become_user] (0x0200): Trying to become user [611030303][611030303]. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [main] (0x0400): Will perform pre-auth (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [k5c_send_data] (0x0200): Received error code 0 (Mon Apr 8 13:57:30 2019) [[sssd[krb5_child[23586]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [23586] finished successfully. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Apr 8 13:57:30 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' (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Mon Apr 8 13:57:30 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' (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [ts_cache] attrs. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #329]: Request handler finished [0]: Success (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #329]: Receiving request data. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #329]: Request removed. (Mon Apr 8 13:57:30 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][splat.acme.com] (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success. (Mon Apr 8 13:57:30 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Mon Apr 8 13:57:30 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate (Mon Apr 8 13:57:32 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #41: New request 'Initgroups by name' (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #41: Parsing input name [myuser@splat.acme.com] (Mon Apr 8 13:57:32 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #41: Setting name [myuser] (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #41: Performing a single domain search (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #41: Search will check the cache and check the data provider (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #41: Using domain [splat.acme.com] (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #41: Preparing input data for domain [splat.acme.com] rules (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #41: Looking up myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #41: Checking negative cache for [myuser@splat.acme.com] (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #41: [myuser@splat.acme.com] is not present in negative cache (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #41: Looking up [myuser@splat.acme.com] in cache (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #41: Returning [myuser@splat.acme.com] from cache (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #41: This request type does not support filtering result by negative cache (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #41: Found 15 entries in domain splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #41: Finished: Success (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 1 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 23585 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #330]: New request. Flags [0000]. (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Apr 8 13:57:32 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 (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Mon Apr 8 13:57:32 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log-20190405 <== (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [main] (0x0400): krb5_child started. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [unpack_buffer] (0x0100): cmd [241] uid [611030303] gid [611030303] validate [true] enterprise principal [false] offline [false] UPN [myuser@SPLAT.acme.com] (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:611030303] old_ccname: [KEYRING:persistent:611030303] keytab: [/etc/krb5.keytab] (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [switch_creds] (0x0200): Switch user to [611030303][611030303]. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/va-prod-ipa01.ipa.splat.acme.com@IPA.SPLAT.acme.com] (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [become_user] (0x0200): Trying to become user [611030303][611030303]. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [main] (0x0400): Will perform online auth (Mon Apr 8 13:57:32 2019) [[sssd[krb5_child[23589]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] (Mon Apr 8 13:57:33 2019) [[sssd[krb5_child[23589]]]] [validate_tgt] (0x0400): TGT verified using key for [host/va-prod-ipa01.ipa.splat.acme.com@IPA.SPLAT.acme.com]. (Mon Apr 8 13:57:33 2019) [[sssd[krb5_child[23589]]]] [create_ccache] (0x0020): 982: [-1750600185][Invalid UID in persistent keyring name] (Mon Apr 8 13:57:33 2019) [[sssd[krb5_child[23589]]]] [map_krb5_error] (0x0020): 1808: [-1750600185][Invalid UID in persistent keyring name] (Mon Apr 8 13:57:33 2019) [[sssd[krb5_child[23589]]]] [k5c_send_data] (0x0200): Received error code 1432158209 (Mon Apr 8 13:57:33 2019) [[sssd[krb5_child[23589]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [23589] finished successfully. (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Apr 8 13:57:33 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 (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #330]: Request handler finished [0]: Success (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #330]: Receiving request data. (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #330]: Request removed. (Mon Apr 8 13:57:33 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Mon Apr 8 13:57:33 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Mon Apr 8 13:57:33 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Mon Apr 8 13:57:33 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Mon Apr 8 13:57:33 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 29 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected! (Mon Apr 8 13:57:34 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. (Mon Apr 8 13:57:34 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Mon Apr 8 13:57:34 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Mon Apr 8 13:57:34 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Mon Apr 8 13:57:34 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23597 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #42: New request 'Initgroups by name' (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #42: Parsing input name [myuser@splat.acme.com] (Mon Apr 8 13:57:34 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #42: Setting name [myuser] (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #42: Performing a single domain search (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #42: Search will check the cache and check the data provider (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #42: Using domain [splat.acme.com] (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #42: Preparing input data for domain [splat.acme.com] rules (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #42: Looking up myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #42: Checking negative cache for [myuser@splat.acme.com] (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #42: [myuser@splat.acme.com] is not present in negative cache (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #42: Looking up [myuser@splat.acme.com] in cache (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #42: Returning [myuser@splat.acme.com] from cache (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #42: This request type does not support filtering result by negative cache (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #42: Found 15 entries in domain splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #42: Finished: Success (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 23597 (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-prod-ipa01.ipa.splat.acme.com (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 23597 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #331]: New request. Flags [0000]. (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Apr 8 13:57:34 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 (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log-20190405 <== (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [main] (0x0400): krb5_child started. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [unpack_buffer] (0x0100): cmd [249] uid [611030303] gid [611030303] validate [true] enterprise principal [false] offline [false] UPN [myuser@SPLAT.acme.com] (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:611030303] old_ccname: [KEYRING:persistent:611030303] keytab: [/etc/krb5.keytab] (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/va-prod-ipa01.ipa.splat.acme.com@IPA.SPLAT.acme.com] (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [become_user] (0x0200): Trying to become user [611030303][611030303]. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [main] (0x0400): Will perform pre-auth (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [k5c_send_data] (0x0200): Received error code 0 (Mon Apr 8 13:57:34 2019) [[sssd[krb5_child[23603]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [23603] finished successfully. (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Apr 8 13:57:34 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' (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Mon Apr 8 13:57:34 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' (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [ts_cache] attrs. (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #331]: Request handler finished [0]: Success (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #331]: Receiving request data. (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #331]: Request removed. (Mon Apr 8 13:57:34 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 ==> /var/log/sssd/sssd_pam.log <== (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][splat.acme.com] (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success. (Mon Apr 8 13:57:34 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Mon Apr 8 13:57:34 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37