I am pretty sure that invalid credentials means that I am typing in the incorrect password, but I promise I am not. I am having an issue where I cannot ssh as a user that is stored in LDAP. I can however use that same user and password to perform a successful ldapsearch and ldapmodify. I am guessing that I have something configured incorrectly. After a day of searching in vain, I have decided to ask people that know better than I do.
I see a couple key parts:
1) In the /var/log/sssd/sssd_pam.log -- You can see that pam_reply is called with a result of 6, which I believe is invalid credentials. 2) In the /var/log/sssd/sssd_default.log -- You can see that things seem to be going well until the we get the message 'Bind result: Invalid credentials(49)'. The simple bind doesn't work. How is this different from ldapsearch?
Any thoughts or ideas?
Thanks,
Kevin
Note: I had to severely truncate some of my logs so I could get this email under the 40K size limit. I can send more log information upon request.
/etc/password-auth:
auth required pam_env.so debug auth [success=done new_authtok_reqd=done auth_err=die perm_denied=die default=ignore] pam_sss.so forward_pass auth sufficient pam_unix.so nullok use_first_pass auth requisite pam_succeed_if.so uid >= 500 quiet auth required pam_deny.so debug
/etc/sssd/sssd.conf:
[domain/default] debug_level = 9
ldap_id_use_start_tls = False cache_credentials = False ldap_search_base = dc=example,dc=com id_provider = ldap auth_provider = ldap access_provider = ldap ldap_group_member = member chpass_provider = ldap ldap_uri = ldaps://test-server/ ldap_tls_cacert = /etc/openldap/certs/cacert.pem
[sssd] debug_level = 9 services = pam config_file_version = 2
domains = default
/etc/openldap/slapd.conf:
TLSCertificateFile /etc/openldap/certs/server.pem TLSCertificateKeyFile /etc/openldap/certs/server.pem TLSCACertificateFile /etc/openldap/certs/cacert.pem TLSVerifyClient allow
# if no access controls are present, the default policy # allows anyone and everyone to read anything but restricts # updates to rootdn. (e.g., "access to * by * read") # # rootdn can always read and write EVERYTHING!
# enable users modifying their own passwords.
access to dn.exact="" by * read
access to attrs=userPassword by self write by anonymous auth by * break
access to dn.subtree="dc=example,dc=com" by dn.exact="uid=jharden,ou=Users,dc=example,dc=com" manage by self write by anonymous read by * none
####################################################################### # database definitions #######################################################################
database bdb suffix "dc=example,dc=com" checkpoint 1024 15
/var/log/sssd/sssd_default.log:
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 636 of server 'test-server' as 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'test-server' as 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=example,dc=com] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=jharden)(objectclass=posixAccount))][dc=example,dc=com]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 2 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16e7840], connected[1], ops[0x1791ec0], ldap[0x16e60a0] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16e7840], connected[1], ops[0x1791ec0], ldap[0x16e60a0] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=jharden,ou=Users,dc=example,dc=com]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16e7840], connected[1], ops[0x1791ec0], ldap[0x16e60a0] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_save_user] (0x2000): Adding originalDN [uid=jharden,ou=Users,dc=example,dc=com] to attributes of [jharden]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [jharden]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20140320231721Z] to attributes of [jharden]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user jharden (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for jharden (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1) (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1) (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [acctinfo_initgroups_callback] (0x0080): NSS Service not conected (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16e7840], connected[1], ops[(nil)], ldap[0x16e60a0] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 16DEE20 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): user: jharden (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): service: sshd (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): tty: ssh (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: test-server (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 1 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 13 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 0 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 0 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 1 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 24982 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'test-server' is 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 636 for server 'test-server' is 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'test-server' is 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server test-server: [127.0.0.1] TTL 7200 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [auth_resolve_done] (0x2000): [ldaps://test-server/] is a secure channel. No need to run START_TLS (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [20] for LDAP connection. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://test-server:636/??base] with fd [20]. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 636 of server 'test-server' as 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'test-server' as 'working' (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x17c0950
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x17c0a70
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x17c0a70 "ltdb_timeout"
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x17c0950 "ltdb_callback"
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [find_password_expiration_attributes] (0x4000): No password policy requested. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [simple_bind_send] (0x0100): Executing simple bind as: uid=jharden,ou=Users,dc=example,dc=com (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [simple_bind_send] (0x2000): ldap simple bind sent, msgid = 1 (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16e4410], connected[1], ops[0x1794440], ldap[0x1791f40] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_BIND] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [simple_bind_done] (0x1000): Server returned no controls. *(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [simple_bind_done] (0x0400): Bind result: Invalid credentials(49), no errmsg set* (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sdap_handle_release] (0x2000): Trace: sh[0x16e4410], connected[1], ops[(nil)], ldap[0x1791f40], destructor_lock[0], release_memory[0] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 6, <NULL>) [Success] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sending result [6][default] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sent result [6][default] (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [cleanup_users] (0x4000): Cache expiration is set to 0 days
/var/log/sssd/sssd_pam.log: (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [jharden@default] (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [jharden] added to PAM initgroup cache (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): domain: default (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): user: jharden (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): rhost: test-server (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 13 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 24982 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x2357220 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x41b300:3:jharden@default] (Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x2357220 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 23568B0 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dp_process_reply] (0x0100): received: [6][default] *(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [6].* (Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_reply] (0x0100): blen: 24 (Thu Mar 20 23:25:04 2014) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x2358760][19] (Thu Mar 20 23:25:04 2014) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x2358760][19] (Thu Mar 20 23:25:04 2014) [sssd[pam]] [client_recv] (0x0200): Client disconnected! (Thu Mar 20 23:25:04 2014) [sssd[pam]] [client_destructor] (0x2000): Terminated client [0x2358760][19] (Thu Mar 20 23:25:09 2014) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [jharden] removed from PAM initgroup cache