Sounds like a problem with the certificate. Can you bind as the user in
question using TLS? (ldapsearch -ZZ -H ldap://server -b <user_dn)
On Sat, Mar 22, 2014 at 10:21 PM, Dmitri Pal <dpal(a)redhat.com> wrote:
On 03/21/2014 08:13 PM, kevin sullivan wrote:
Thanks for the quick response Dmitri. I have been looking through the
server logs and trying to find anything that sticks out as an error and I
don't know what I am looking for. I can see an initial certificate passing
and things seem to proceed without issue from there. I can see where it
looks for the different attributes of my user like the group memberships,
but I don't see anything that pops out at me. The only error that I see a
couple:
TLS certificate verification: subject: no certificate, issuer: no
certificate, cipher: Camellia-256, security level: high, secret key bits:
256, total key bits: 256, cache hits: 0, cache misses: 4, cache not
reusable: 0
connection_read(14): unable to get TLS client DN, error=49 id=1004
I have recently added the option 'ldap_tls_reqcert = allow', so I was
hoping this wouldn't actually be an error.
I am going to mess around with the certificates some more because it
does seem like a good direction to follow. I am connecting to my ldap
server via ldaps and I do use certificates when running ldapsearch and
ldapmodify. I must be missing something in my sssd.conf.
You mentioned that some controls are required for sssd to work properly.
Where can I find a good list of these?
I hope some of the SSSD team members would be able to give you some hints.
I specifically allow access to the RootDSE and I turned off password
policy support to hopefully remove another variable from my problem.
On Fri, Mar 21, 2014 at 2:14 PM, Dmitri Pal <dpal(a)redhat.com> wrote:
> On 03/21/2014 01:11 PM, kevin sullivan wrote:
>
> 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?
>
> I am not an expert in SSSD internals so this is an answer from my
> general knowledge about the project.
> SSSD is more picky than simple bind done by ldapsearch or ldapmodify. It
> requires some kind of authentication. If you do not use any security of the
> connection it will fail.
> It seems like TLS is disabled in you setup and bind might be happening in
> clear. SSSD would not do that.
> However there can be another issue. May be the server is configured to
> not to return controls that SSSD expects. For example it expects the server
> t oreturn information about password aging so that if password needs change
> the user can be correctly prompted for the change.
>
> I would start with the server logs and check if the bind is successful or
> not. If it fails on the handshake phase this would be probably cased by the
> first issue. If it goes through fine and bind is successful then it might
> be related to controls.
>
> HTH
> Dmitri
>
>
> 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
>
>
> _______________________________________________
> sssd-users mailing
listsssd-users@lists.fedorahosted.orghttps://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/
>
>
> _______________________________________________
> sssd-users mailing list
> sssd-users(a)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/
_______________________________________________
sssd-users mailing list
sssd-users(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users