[SSSD-users] System Error 4 with CentOS 7.1 IPA clients attempting password authentication

Ken Miller kenmiller316 at gmail.com
Tue Aug 25 15:46:31 UTC 2015


Password Prompt occurred HERE:

[be_get_account_info] (0x0200): Got request for [0x3][1][name=testuser1]
[be_req_set_domain] (0x0400): Changing request domain from [example.com] to
[example.com]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
[sdap_get_initgr_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=example,dc=com]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uid=testuser1)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=example,dc=com].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_save_user] (0x0400): Save user
[sdap_get_primary_name] (0x0400): Processing object testuser1
[sdap_save_user] (0x0400): Processing user testuser1
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
[sdap_save_user] (0x0400): Adding original memberOf attributes to
[testuser1].
[sdap_save_user] (0x0400): Adding user principal [testuser1 at EXAMPLE.COM] to
attributes of [testuser1].
[sdap_save_user] (0x0400): Storing info for user testuser1
[sdap_get_primary_name] (0x0400): Processing object testuser1
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=example,dc=com].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_get_primary_name] (0x0400): Processing object ipausers
[sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
domain SID from [(null)]
[sdap_get_groups_next_base] (0x0400): Searching for groups with base
[cn=accounts,dc=example,dc=com]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(gidNumber=100)(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=example,dc=com].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
[be_req_set_domain] (0x0400): Changing request domain from [example.com] to
[example.com]
[be_pam_handler] (0x0100): Got request with the following data
[pam_print_data] (0x0100): command: PAM_AUTHENTICATE
[pam_print_data] (0x0100): domain: example.com
[pam_print_data] (0x0100): user: testuser1
[pam_print_data] (0x0100): service: sshd
[pam_print_data] (0x0100): tty: ssh
[pam_print_data] (0x0100): ruser:
[pam_print_data] (0x0100): rhost: testremote.example.com
[pam_print_data] (0x0100): authtok type: 1
[pam_print_data] (0x0100): newauthtok type: 0
[pam_print_data] (0x0100): priv: 1
[pam_print_data] (0x0100): cli_pid: 23360
[pam_print_data] (0x0100): logon name: not set
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[ipa_resolve_callback] (0x0400): Constructed uri 'ldap://
testipasvr.example.com'
[write_pipe_handler] (0x0400): All data has been sent!
[child_sig_handler] (0x0100): child [23366] finished successfully.
[read_pipe_handler] (0x0400): EOF received, client finished
[fo_set_port_status] (0x0100): Marking port 389 of server '
testipasvr.example.com' as 'working'
[set_server_common_status] (0x0100): Marking server 'testipasvr.example.com'
as 'working'
[fo_set_port_status] (0x0400): Marking port 389 of duplicate server '
testipasvr.example.com' as 'working'
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
[Success]
[be_pam_handler_callback] (0x0100): Sending result [0][example.com]
[be_pam_handler_callback] (0x0100): Sent result [0][example.com]
[be_req_set_domain] (0x0400): Changing request domain from [example.com] to
[example.com]
[be_pam_handler] (0x0100): Got request with the following data
[pam_print_data] (0x0100): command: PAM_ACCT_MGMT
[pam_print_data] (0x0100): domain: example.com
[pam_print_data] (0x0100): user: testuser1
[pam_print_data] (0x0100): service: sshd
[pam_print_data] (0x0100): tty: ssh
[pam_print_data] (0x0100): ruser:
[pam_print_data] (0x0100): rhost: testremote.example.com
[pam_print_data] (0x0100): authtok type: 0
[pam_print_data] (0x0100): newauthtok type: 0
[pam_print_data] (0x0100): priv: 1
[pam_print_data] (0x0100): cli_pid: 23360
[pam_print_data] (0x0100): logon name: not set
[sdap_access_send] (0x0400): Performing access check for user [testuser1]
[sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user
[testuser1]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=testhost.example.com
))][cn=accounts,dc=example,dc=com].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[ipa_host_info_done] (0x0020): Server does not support deref
[sdap_id_op_done] (0x0200): communication error on cached connection,
moving to next server
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[ipa_resolve_callback] (0x0400): Constructed uri 'ldap://
testipasvr.example.com'
[sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectclass=*)][].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_kinit_send] (0x0400): Attempting kinit (default, host/
testhost.example.com, EXAMPLE.COM, 86400)
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[create_tgt_req_send_buffer] (0x0400): buffer size: 80
[set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
[write_pipe_handler] (0x0400): All data has been sent!
[child_sig_handler] (0x0100): child [23368] finished successfully.
[read_pipe_handler] (0x0400): EOF received, client finished
[sdap_get_tgt_recv] (0x0400): Child responded: 0
[FILE:/var/lib/sss/db/ccache_EXAMPLE.COM], expired on [1440601460]
[sdap_cli_auth_step] (0x0100): expire timeout is 900
[sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user: host/
testhost.example.com
[fo_set_port_status] (0x0100): Marking port 389 of server '
testipasvr.example.com' as 'working'
[set_server_common_status] (0x0100): Marking server 'testipasvr.example.com'
as 'working'
[fo_set_port_status] (0x0400): Marking port 389 of duplicate server '
testipasvr.example.com' as 'working'
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=testhost.example.com
))][cn=accounts,dc=example,dc=com].
[be_run_unconditional_online_cb] (0x0400): Running unconditional online
callbacks.
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[ipa_host_info_done] (0x0020): Server does not support deref
[sdap_id_op_done] (0x0200): communication error on cached connection,
moving to next server
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectclass=*)][].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_kinit_send] (0x0400): Attempting kinit (default, host/
testhost.example.com, EXAMPLE.COM, 86400)
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[create_tgt_req_send_buffer] (0x0400): buffer size: 80
[set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
[write_pipe_handler] (0x0400): All data has been sent!
[child_sig_handler] (0x0100): child [23369] finished successfully.
[read_pipe_handler] (0x0400): EOF received, client finished
[sdap_get_tgt_recv] (0x0400): Child responded: 0
[FILE:/var/lib/sss/db/ccache_EXAMPLE.COM], expired on [1440601460]
[sdap_cli_auth_step] (0x0100): expire timeout is 900
[sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user: host/
testhost.example.com
[fo_set_port_status] (0x0100): Marking port 389 of server '
testipasvr.example.com' as 'working'
[set_server_common_status] (0x0100): Marking server 'testipasvr.example.com'
as 'working'
[fo_set_port_status] (0x0400): Marking port 389 of duplicate server '
testipasvr.example.com' as 'working'
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=testhost.example.com
))][cn=accounts,dc=example,dc=com].
[be_run_unconditional_online_cb] (0x0400): Running unconditional online
callbacks.
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[ipa_host_info_done] (0x0020): Server does not support deref
[sdap_id_op_done] (0x0200): communication error on cached connection,
moving to next server
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectclass=*)][].
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[sdap_kinit_send] (0x0400): Attempting kinit (default, host/
testhost.example.com, EXAMPLE.COM, 86400)
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
[be_resolve_server_process] (0x0200): Found address for server
testipasvr.example.com: [10.10.1.47] TTL 1200
[create_tgt_req_send_buffer] (0x0400): buffer size: 80
[set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
[write_pipe_handler] (0x0400): All data has been sent!
[child_sig_handler] (0x0100): child [23370] finished successfully.
[read_pipe_handler] (0x0400): EOF received, client finished
[sdap_get_tgt_recv] (0x0400): Child responded: 0
[FILE:/var/lib/sss/db/ccache_EXAMPLE.COM], expired on [1440601460]
[sdap_cli_auth_step] (0x0100): expire timeout is 900
[sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user: host/
testhost.example.com
[fo_set_port_status] (0x0100): Marking port 389 of server '
testipasvr.example.com' as 'working'
[set_server_common_status] (0x0100): Marking server 'testipasvr.example.com'
as 'working'
[fo_set_port_status] (0x0400): Marking port 389 of duplicate server '
testipasvr.example.com' as 'working'
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaHost)(fqdn=testhost.example.com
))][cn=accounts,dc=example,dc=com].
[be_run_unconditional_online_cb] (0x0400): Running unconditional online
callbacks.
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
[ipa_host_info_done] (0x0020): Server does not support deref
[sdap_id_op_done] (0x0200): communication error on cached connection,
moving to next server
[be_pam_handler_callback] (0x0100): Backend returned: (3, 4, <NULL>)
[Internal Error (System error)]
[be_pam_handler_callback] (0x0100): Sending result [4][example.com]
[be_pam_handler_callback] (0x0100): Sent result [4][example.com]
[be_run_unconditional_online_cb] (0x0400): Running unconditional online
callbacks.

End of debug log after error HERE


/var/log/secure reported HERE
sshd[23360]: pam_unix(sshd:auth): authentication failure; logname= uid=0
euid=0 tty=ssh ruser= rhost=testremote.example.com  user=testuser1
sshd[23360]: pam_sss(sshd:auth): authentication success; logname= uid=0
euid=0 tty=ssh ruser= rhost=testremote.example.com user=testuser1
sshd[23360]: pam_sss(sshd:account): Access denied for user testuser1: 4
(System error)
sshd[23360]: Failed password for testuser1 from 10.10.2.46 port 52467 ssh2
sshd[23360]: fatal: Access denied for user testuser1 by PAM account
configuration [preauth]

stdout/stderr reported HERE
ssh testuser1 at testhost
testuser1 at testhost's password:
Connection closed by UNKNOWN
#
sssd.conf HERE
[domain/example.com]
debug_level=6
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = example.com
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = testhost.example.com
chpass_provider = ipa
ipa_dyndns_update = True
ipa_server = _srv_, testipasvr.example.com
ldap_tls_cacert = /etc/ipa/ca.crt
ldap_deref_threshold = 0
enumerate = False
autofs_provider = ipa
ipa_automount_location = inc
[sssd]
services = nss, sudo, pam, autofs, ssh
config_file_version = 2

domains = example.com
[nss]
homedir_substring = /home
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20150825/4091981a/attachment-0001.html>


More information about the sssd-users mailing list