I am not an expert in SSSD internals so this is an answer from my general knowledge about the project.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 debugauth [success=done new_authtok_reqd=done auth_err=die perm_denied=die default=ignore] pam_sss.so forward_passauth sufficient pam_unix.so nullok use_first_passauth requisite pam_succeed_if.so uid >= 500 quietauth required pam_deny.so debug
/etc/sssd/sssd.conf:
[domain/default]debug_level = 9
ldap_id_use_start_tls = Falsecache_credentials = Falseldap_search_base = dc=example,dc=comid_provider = ldapauth_provider = ldapaccess_provider = ldapldap_group_member = memberchpass_provider = ldapldap_uri = ldaps://test-server/ldap_tls_cacert = /etc/openldap/certs/cacert.pem
[sssd]debug_level = 9services = pamconfig_file_version = 2
domains = default
/etc/openldap/slapd.conf:
TLSCertificateFile /etc/openldap/certs/server.pemTLSCertificateKeyFile /etc/openldap/certs/server.pemTLSCACertificateFile /etc/openldap/certs/cacert.pemTLSVerifyClient 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=userPasswordby self writeby anonymous authby * break
access to dn.subtree="dc=example,dc=com"by dn.exact="uid=jharden,ou=Users,dc=example,dc=com" manageby self writeby anonymous readby * none
######################################################################## database definitions#######################################################################
database bdbsuffix "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
_______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
-- Thank you, Dmitri Pal Sr. Engineering Manager for IdM portfolio Red Hat Inc. ------------------------------- Looking to carve out IT costs? www.redhat.com/carveoutcosts/