Hide Forgot
Description of problem: I have an IPA client (with F24) on which any ipa user cannot log in. I get a system error for pam_sss (see logs below) when user 'smith' tries to log in. Also in the logs in /var/log/sssd/sssd_opera.log, it finds a server named 'zaira' (which is the replica server). Insn't it supposed to find the ipa server (which is named 'zaira2' but does not appear nowhere in the logs)? All the config files located in /etc refer to server zaira2. I do not have this problem with my other ipa clients. Version-Release number of selected component (if applicable): sssd-1.14.2-1.fc24.x86_64 sssd-ad-1.14.2-1.fc24.x86_64 sssd-client-1.14.2-1.fc24.x86_64 sssd-common-1.14.2-1.fc24.x86_64 sssd-common-pac-1.14.2-1.fc24.x86_64 sssd-ipa-1.14.2-1.fc24.x86_64 sssd-krb5-1.14.2-1.fc24.x86_64 sssd-krb5-common-1.14.2-1.fc24.x86_64 sssd-ldap-1.14.2-1.fc24.x86_64 sssd-nfs-idmap-1.14.2-1.fc24.x86_64 sssd-proxy-1.14.2-1.fc24.x86_64 How reproducible: I don't know how to reproduce this problem on another client. Actual results: /var/log/secure: Nov 9 08:46:05 nina sshd[22951]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.21.200 user=smith Nov 9 08:46:05 nina sshd[22951]: pam_sss(sshd:account): Access denied for user smith: 4 (System error) Nov 9 08:46:05 nina sshd[22951]: Failed password for smith from 10.0.21.200 port 42166 ssh2 Nov 9 08:46:05 nina sshd[22951]: fatal: Access denied for user smith by PAM account configuration [preauth] /var/log/sssd/sssd_opera.log (with debug_level = 6): (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=nobody@opera] (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [Account #315]: New request. Flags [0x0001]. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=opera] (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=nobody)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=opera]. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [nobody@opera] found. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_search_entry_by_sid_str] (0x0400): No such entry (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_search_object_by_str_attr] (0x0400): No such entry. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_get_real_name] (0x0040): Cannot find user [nobody@opera] in cache (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [Account #315]: Request handler finished [0]: Success (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [Account #315]: Receiving request data. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #315]: Finished. Success. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3:1::opera:name=nobody@opera] from reply table (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [Account #315]: Request removed. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=smith@opera] (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [Account #316]: New request. Flags [0000]. (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=accounts,dc=opera] (Wed Nov 9 09:09:09 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=smith)(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=opera]. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_search_user_process] (0x0400): Search for users, returned 1 results. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Save user (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_get_primary_name] (0x0400): Processing object smith (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Processing user smith@opera (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [smith@opera]. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Adding user principal [smith@OPERA] to attributes of [smith@opera]. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Storing info for user smith@opera (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:IPA:opera:31f538c2-9f16-11e5-981a-141877268ef2))][cn=Default Trust View,cn=views,cn=accounts,dc=opera]. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [Account #316]: Request handler finished [0]: Success (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [Account #316]: Receiving request data. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #316]: Finished. Success. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0000:1:1::opera:name=smith@opera] from reply table (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [Account #316]: Request removed. (Wed Nov 9 09:09:10 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=smith@opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [Initgroups #317]: New request. Flags [0000]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=smith)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Save user (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_primary_name] (0x0400): Processing object smith (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Processing user smith@opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [smith@opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Adding user principal [smith@OPERA] to attributes of [smith@opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_save_user] (0x0400): Storing info for user smith@opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_primary_name] (0x0400): Processing object smith (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*))][cn=opera,cn=groups,cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_primary_name] (0x0400): Processing object ipausers (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_primary_name] (0x0400): Processing object opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_initgr_done] (0x0400): Primary group already cached, nothing to do. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:IPA:opera:31f538c2-9f16-11e5-981a-141877268ef2))][cn=Default Trust View,cn=views,cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [Initgroups #317]: Request handler finished [0]: Success (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #317]: Receiving request data. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_initgr_pp] (0x0400): Ordering NSS responder to update memory cache (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #317]: Finished. Success. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0000:3:1::opera:name=smith@opera] from reply table (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #317]: Request removed. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_pam_handler] (0x0100): Got request with the following data (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): domain: opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): user: smith@opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): service: sshd (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): tty: ssh (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): ruser: (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): rhost: 10.0.21.200 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): priv: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): cli_pid: 23300 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): logon name: not set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #318]: New request. Flags [0000]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [be_resolve_server_process] (0x0200): Found address for server zaira.opera: [10.0.21.17] TTL 1200 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://zaira.opera' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [set_server_common_status] (0x0100): Marking server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #318]: Request handler finished [0]: Success (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #318]: Receiving request data. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #318]: Request removed. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [child_sig_handler] (0x0100): child [23303] finished successfully. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_pam_handler] (0x0100): Got request with the following data (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): domain: opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): user: smith@opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): service: sshd (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): tty: ssh (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): ruser: (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): rhost: 10.0.21.200 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): authtok type: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): priv: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): cli_pid: 23300 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): logon name: not set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #319]: New request. Flags [0000]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [be_resolve_server_process] (0x0200): Found address for server zaira.opera: [10.0.21.17] TTL 1200 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://zaira.opera' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [child_sig_handler] (0x0100): child [23304] finished successfully. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [set_server_common_status] (0x0100): Marking server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'zaira.opera' as 'working' (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #319]: Request handler finished [0]: Success (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #319]: Receiving request data. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #319]: Request removed. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_pam_handler] (0x0100): Got request with the following data (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): domain: opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): user: smith@opera (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): service: sshd (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): tty: ssh (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): ruser: (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): rhost: 10.0.21.200 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): priv: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): cli_pid: 23300 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [pam_print_data] (0x0100): logon name: not set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [PAM Account #320]: New request. Flags [0000]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_access_send] (0x0400): Performing access check for user [smith@opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [smith@opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_account_expired] (0x0400): IPA access control succeeded, checking AD access control (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_account_expired_ad] (0x0400): Performing AD access check for user [smith@opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=nina.opera))][cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=nina.opera,cn=computers,cn=accounts,dc=opera] using OpenLDAP deref (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_send] (0x0400): WARNING: Disabling paging because scope is set to base. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=nina.opera,cn=computers,cn=accounts,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_hostgroup_info_done] (0x0200): No host groups were dereferenced (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_hbac_service_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=opera][2][(objectClass=ipaHBACService)] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACService)][cn=hbac,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=opera][2][(objectClass=ipaHBACServiceGroup)] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACServiceGroup)][cn=hbac,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_hbac_rule_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=opera][2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(accessRuleType=allow)(|(hostCategory=all)(memberHost=fqdn=nina.opera,cn=computers,cn=accounts,dc=opera)))] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(accessRuleType=allow)(|(hostCategory=all)(memberHost=fqdn=nina.opera,cn=computers,cn=accounts,dc=opera)))][cn=hbac,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule [allow_all] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_evaluate] (0x0100): [< hbac_evaluate() (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_evaluate] (0x0100): ALLOWED by rule [allow_all]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [hbac_evaluate] (0x0100): hbac_evaluate() >] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [allow_all] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [PAM Account #320]: Request handler finished [0]: Success (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [PAM Account #320]: Receiving request data. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [PAM Account #320]: Request removed. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): DP Request [PAM SELinux #321]: New request. Flags [0000]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_get_selinux_send] (0x0400): Retrieving SELinux user mapping (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipaConfig)(objectClass=ipaGuiConfig))][cn=etc,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_selinux_get_maps_next] (0x0400): Trying to fetch SELinux maps with following parameters: [2][(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=opera] (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=opera]. (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [ipa_selinux_get_maps_done] (0x0400): No SELinux user maps found! (Wed Nov 9 09:09:12 2016) [sssd[be[opera]]] [sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0 (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [selinux_child_done] (0x0020): selinux_child_parse_response failed: [22][Invalid argument] (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [PAM SELinux #321]: Request handler finished [0]: Success (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [_dp_req_recv] (0x0400): DP Request [PAM SELinux #321]: Receiving request data. (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): DP Request [PAM SELinux #321]: Request removed. (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [child_sig_handler] (0x0020): child [23306] failed with status [1].
Can you please attach the full logs? It's not clear to me which request returns the system error. Although I see the selinux child failed here, the return value from the selinux operation seems to return 0: (Wed Nov 9 09:09:13 2016) [sssd[be[opera]]] [dp_req_done] (0x0400): DP Request [PAM SELinux #321]: Request handler finished [0]: Success
IIRC there should be selinux_child.log. I suspect some issues with libsemanage. I already saw such report on IRC but user did not reply anymore :-( So we could not fix it.
Created attachment 1218862 [details] /var/log/secure
Created attachment 1218864 [details] /var/log/sssd/sssd_opera.log
SElinux is disabled on that client as well as on the other clients.
Created attachment 1218885 [details] /var/log/sssd/selinux_child.log
Petr, Could you look into selinux_child.log The following error from libsemanage is suspicious to me "Unable to read BackupPC module lang ext file."
I wonder if this is a bug or a feature. If the IPA server wants us to set a SELinux context but SELinux is disabled how should SSSD handle this? Maybe it would be more consistent to say that if you want to disable SELinux on an IPA client you have to disable SSSD's SELinux provider as well?
What do you mean by "disable SSSD's SELinux provider"? how would I do that?
If SELinux is disabled, SSSD should detect and refrain from using it at runtime automatically.
(In reply to Simo Sorce from comment #10) > If SELinux is disabled, SSSD should detect and refrain from using it at > runtime automatically. That's not a solution it's a workaround and there are more possible workarounds. It would be much better to fix root of cause and probably prevent such situations either in selinux_child or libsemanage
I do not understand what you mean by definiying it a workaround ? If SELinux is disabled, then SSSD should not perform operations related to SELinux, this is not a workaround but a statement of the expected behavior SSSD should have. It can be easily done by a call to is_selinux_enabled() and then managed at runtime.
(In reply to Simo Sorce from comment #12) > I do not understand what you mean by definiying it a workaround ? > > If SELinux is disabled, then SSSD should not perform operations related to > SELinux, this is not a workaround but a statement of the expected behavior > SSSD should have. > > It can be easily done by a call to is_selinux_enabled() and then managed at > runtime. I would recommend you to read description of this bug more carefully. There is written: 'I do not have this problem with my other ipa clients.' So if there is not any problem with selinux_child on other clients then recommendation to switch SELinux into disabled mode is just a workaround and not a solution. It will just hide symptoms on one machine. It will not solve a bug in selinux_child/libsemanage.
(In reply to Lukas Slebodnik from comment #7) > Petr, > Could you look into selinux_child.log > The following error from libsemanage is suspicious to me > "Unable to read BackupPC module lang ext file." It looks like that SELinux module store is somehow corrupted. There's a probably /var/lib/selinux/active/modules/*/BackupPC directory with empty /var/lib/selinux/active/modules/*/BackupPC/lang_ext file. I don't know what is expected function of BackupPC module. The directory can be either remove completely removed; or you can try to fix lang_ext file using a file with the same name from different module.
OK, I had this: # ll /var/lib/selinux/targeted/active/modules/400/ drwx------ 2 root root 4096 Jun 6 14:55 BackupPC drwx------ 2 root root 4096 Jun 6 14:55 docker # ll /var/lib/selinux/targeted/active/modules/400/BackupPC -rw-r--r-- 1 root root 0 Jun 6 14:55 cil -rw-r--r-- 1 root root 0 Jun 6 14:55 hll -rw-r--r-- 1 root root 0 Jun 6 14:55 lang_ext Here files are empty. So I removed both directories, BackupPC and docker. an then logged in as smith successfully this time on that ipa client and got this log (in /var/log/sssd/selinux_child.log) (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28963]]]] [pack_buffer] (0x0400): result [0] (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28963]]]] [main] (0x0400): selinux_child completed successfully (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [main] (0x0400): selinux_child started. (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [main] (0x0400): context initialized (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [main] (0x0400): performing selinux operations (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [get_seuser] (0x0040): SELinux user for smith: unconfined_u (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [get_seuser] (0x0040): SELinux range for smith: s0-s0:c0.c1023 (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [pack_buffer] (0x0400): result [0] (Wed Nov 9 17:02:00 2016) [[sssd[selinux_child[28977]]]] [main] (0x0400): selinux_child completed successfully On another ipa client where I always could log in successfully, I had non-empty files in /var/lib/selinux/targeted/active/modules/400/BackupPC. So, thank you, Petr. Your solution solved the problem.
(In reply to Simo Sorce from comment #12) > I do not understand what you mean by definiying it a workaround ? > > If SELinux is disabled, then SSSD should not perform operations related to > SELinux, this is not a workaround but a statement of the expected behavior > SSSD should have. > > It can be easily done by a call to is_selinux_enabled() and then managed at > runtime. btw this would have positive performance impact. Calling the semanage functions does not come for free (IIRC semanage recursively copies a directory structure it uses iternally) and even though we try to detect if calling semanage is needed at all (by comparing known and new SELinux context), I think not running the code at all would further improve performance in case SELinux is not needed anyway.
sssd does not directly touch anything in /var/lib/selinux/*. We could not truncate them. We use libsemanage in sssd. I think that empty file should be either ignored or better message should be logged then "Unable to read BackupPC module lang ext file." Assigning to libsemanage; feel free to close if there is nothing to improve in libsemanage.
So the question is who, when and why created/imported BackupPC module. Do you know where it comes from? It's not a part of selinux-policy. It could be originated in some 3rd party package? libsemanage uses sandbox tmp directory where it works with modules and if everything is ok, it moves it to active. Users are not supposed to manipulates files directly in /var/lib/selinux.
I have to say that after I removed directory /var/lib/selinux/targeted/active/modules/400/BackupPC, I tried to log in as smith on that ipa client and got the same error message with directory /var/lib/selinux/targeted/active/modules/400/docker "Unable to read docker module lang ext file.". So I removed it as well and then I could log in successfully. So it is not a BackupPC specific problem.
(In reply to Petr Lautrbach from comment #18) > So the question is who, when and why created/imported BackupPC module. Do > you know where it comes from? It's not a part of selinux-policy. It could be > originated in some 3rd party package? Probably from: $ dnf info backuppc Last metadata expiration check: 0:19:48 ago on Wed Nov 9 21:34:25 2016. Available Packages Name : BackupPC Arch : x86_64 Epoch : 0 Version : 3.3.1 Release : 6.fc24 Size : 416 k Repo : updates Summary : High-performance backup system URL : http://backuppc.sourceforge.net/ License : GPLv2+ Description : BackupPC is a high-performance, enterprise-grade system for backing up Linux : and WinXX and Mac OS X PCs and laptops to a server's disk. BackupPC is highly : configurable and easy to install and maintain.
This message is a reminder that Fedora 24 is nearing its end of life. Approximately 2 (two) weeks from now Fedora will stop maintaining and issuing updates for Fedora 24. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '24'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 24 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 24 changed to end-of-life (EOL) status on 2017-08-08. Fedora 24 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.