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