Hello, I suspect this is a result of outdated software; however, the "Trouble-shooting" guide (URL https://fedorahosted.org/sssd/wiki/Troubleshooting ) requested I post occurrences of "System Error 4" encountered to this list...
My IPA Server is RHEL65 running ipa-server-3.0.0-37.el6.x86_64 in a lab environment. Other RHEL65 clients haven't demonstrated this problem, but CentOS71 clients running ipa-client-4.1.0-18.el7.centos.3.x86_64 fail to accept password authentication and report messages similar to the following in /var/log/secure :
Aug 24 10:34:49 testhost sshd[17787]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=testhost.example.com user=testuser1 Aug 24 10:34:49 testhost sshd[17787]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost= testhost.example.com user=testuser1 Aug 24 10:34:49 testhost sshd[17787]: pam_sss(sshd:account): Access denied for user testuser1: 4 (System error) Aug 24 10:34:49 testhost sshd[17787]: Failed password for testuser1 from 10.10.1.232 port 39617 ssh2 Aug 24 10:34:49 testhost sshd[17787]: fatal: Access denied for user testuser1 by PAM account configuration [preauth]
Help much appreciated in tracking down/fixing the root cause.
Thanks in advance,
== k+ ==
On (25/08/15 08:42), Ken Miller wrote:
Hello, I suspect this is a result of outdated software; however, the "Trouble-shooting" guide (URL https://fedorahosted.org/sssd/wiki/Troubleshooting ) requested I post occurrences of "System Error 4" encountered to this list...
Yes, but we would need to see a log files from sssd :-) See wiki page for more info.
My IPA Server is RHEL65 running ipa-server-3.0.0-37.el6.x86_64 in a lab environment. Other RHEL65 clients haven't demonstrated this problem, but CentOS71 clients running ipa-client-4.1.0-18.el7.centos.3.x86_64 fail to accept password authentication and report messages similar to the following in /var/log/secure :
There should not be a problem with old ipa-server (rhel 6.5) But could you re-test with the latest sssd 1.12 version? https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12/
LS
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@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@testhost testuser1@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
On (25/08/15 11:46), Ken Miller wrote:
Password Prompt occurred HERE:
[ipa_host_info_done] (0x0020): Server does not support deref
This message is suspicious.
[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
Could you try to re-test with the latest sssd 1.12 version? https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12/
If it does not help then could you upgrade ipa server to the latest rhel 6.7? There is still ipa 3.0 but there were fixes to 389-ds and other components.
LS
Hi Lukas,
Thanks! The latest sssd-1.12.5-3.el7.centos.x86_64 did NOT work any differently. Based on info I found in https://fedorahosted.org/freeipa/ticket/4486 I'm thinking I should bite the bullet and go with a 4.1 server (e.g. what's in CentOS 7.1) like ipa-server-4.1.0-18.el7.centos.3.x86_64 . Might even be time to try it in a docker container ;).
Regards,
== k+ ==
On Tue, Aug 25, 2015 at 12:27 PM, Lukas Slebodnik lslebodn@redhat.com wrote:
On (25/08/15 11:46), Ken Miller wrote:
Password Prompt occurred HERE:
[ipa_host_info_done] (0x0020): Server does not support deref
This message is suspicious.
[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
Could you try to re-test with the latest sssd 1.12 version? https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12/
If it does not help then could you upgrade ipa server to the latest rhel 6.7? There is still ipa 3.0 but there were fixes to 389-ds and other components.
LS _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On (25/08/15 15:01), Ken Miller wrote:
Hi Lukas,
Thanks! The latest sssd-1.12.5-3.el7.centos.x86_64 did NOT work any differently.
sssd-1.12.5 should work well with the latest ipa-3.0 on el6.7.
[sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server
Did you get the same error with sssd-1.12.5?
LS
sssd-users@lists.fedorahosted.org
-
Ken Miller -
Lukas Slebodnik