[SSSD-users] SSSD + SSH Invalid Credentials

Discussion:

kevin sullivan

2014-03-21 17:11:37 UTC

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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140321/bd826d90/attachment-0001.html>

Dmitri Pal

2014-03-21 18:14:25 UTC

Permalink

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

Post by kevin sullivan
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.
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
[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
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
#######################################################################
databasebdb
suffix"dc=example,dc=com"
checkpoint1024 15
(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]
(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
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
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_check_user_search]
(0x0400): Returning info for user [jharden at default]
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_initgr_cache_set]
(0x2000): [jharden] added to PAM initgroup cache
command: PAM_AUTHENTICATE
domain: default
user: jharden
service: sshd
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
ruser: not set
rhost: test-server
authtok type: 1
authtok size: 13
newauthtok type: 0
newauthtok size: 0
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
cli_pid: 24982
0x2357220
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 at default]
0x2357220
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 23568B0
Dispatching.
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dp_process_reply]
(0x0100): received: [6][default]
pam_reply called with result [6].*
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_reply] (0x0100): blen: 24
Idle timer re-set for client [0x2358760][19]
Idle timer re-set for client [0x2358760][19]
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [client_recv] (0x0200): Client
disconnected!
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 at 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/

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140321/46074cc7/attachment-0001.html>

kevin sullivan

2014-03-22 00:13:02 UTC

Permalink

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 specifically allow access to the
RootDSE and I turned off password policy support to hopefully remove
another variable from my problem.

Post by kevin sullivan
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.
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.
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
[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
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
(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
Save user
Adding originalDN [uid=jharden,ou=Users,dc=example,dc=com] to attributes of
[jharden].
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
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!
dbus conn: 16DEE20
Dispatching.
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sbus_message_handler]
(0x4000): Received SBUS method [pamHandler]
Got request with the following data
command: PAM_AUTHENTICATE
domain: default
user: jharden
service: sshd
tty: ssh
rhost: test-server
authtok type: 1
authtok size: 13
newauthtok type: 0
newauthtok size: 0
priv: 1
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'
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
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)
Cache expiration is set to 0 days
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_check_user_search]
(0x0400): Returning info for user [jharden at default]
[jharden] added to PAM initgroup cache
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
PAM_AUTHENTICATE
default
jharden
sshd
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
not set
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
newauthtok type: 0
newauthtok size: 0
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
24982
0x2357220
pam_dp_send_req returned 0
Deleting request: [0x41b300:3:jharden at default]
0x2357220
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 23568B0
Dispatching.
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!
Terminated client [0x2358760][19]
[jharden] removed from PAM initgroup cache
_______________________________________________
sssd-users mailing listsssd-users at 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 at lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140321/27c470a9/attachment-0001.html>

Dmitri Pal

2014-03-22 21:21:23 UTC

Permalink

Post by kevin sullivan
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
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.

Post by kevin sullivan
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 at redhat.com

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

Post by kevin sullivan
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.
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
[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
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
#######################################################################
databasebdb
suffix"dc=example,dc=com"
checkpoint1024 15
(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]]]
[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]]]
[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
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
start ldb transaction (nesting: 1)
commit ldb transaction (nesting: 1)
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]
(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'
Added timed event "ltdb_callback": 0x17c0950
Added timed event "ltdb_timeout": 0x17c0a70
Destroying timer event 0x17c0a70 "ltdb_timeout"
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]
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]
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
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_check_user_search]
(0x0400): Returning info for user [jharden at 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]
command: PAM_AUTHENTICATE
domain: default
user: jharden
service: sshd
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
ruser: not set
rhost: test-server
authtok type: 1
authtok size: 13
newauthtok type: 0
newauthtok size: 0
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
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 at default]
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_remove_timeout]
(0x2000): 0x2357220
dbus conn: 23568B0
Dispatching.
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_dp_process_reply]
(0x0100): received: [6][default]
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]
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 at lists.fedorahosted.org <mailto:sssd-users at 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/ <http://www.redhat.com/carveoutcosts/>
_______________________________________________
sssd-users mailing list
sssd-users at lists.fedorahosted.org
<mailto:sssd-users at lists.fedorahosted.org>
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

Jakub Hrozek

2014-03-23 21:16:37 UTC

Permalink

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)

Post by kevin sullivan
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
TLS certificate verification: subject: no certificate, issuer: no
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.

Post by kevin sullivan
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.
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.
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
[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
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
(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
Save user
Adding originalDN [uid=jharden,ou=Users,dc=example,dc=com] to attributes of
[jharden].
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!
dbus conn: 16DEE20
Dispatching.
(Thu Mar 20 23:25:04 2014) [sssd[be[default]]] [sbus_message_handler]
(0x4000): Received SBUS method [pamHandler]
Got request with the following data
command: PAM_AUTHENTICATE
domain: default
user: jharden
service: sshd
tty: ssh
rhost: test-server
authtok type: 1
authtok size: 13
newauthtok type: 0
newauthtok size: 0
priv: 1
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]]]
[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
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)
Cache expiration is set to 0 days
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_check_user_search]
(0x0400): Returning info for user [jharden at default]
[jharden] added to PAM initgroup cache
command: PAM_AUTHENTICATE
default
jharden
service: sshd
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
not set
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
newauthtok type: 0
newauthtok size: 0
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
cli_pid: 24982
0x2357220
pam_dp_send_req returned 0
Deleting request: [0x41b300:3:jharden at default]
0x2357220
(Thu Mar 20 23:25:04 2014) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 23568B0
Dispatching.
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!
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 at 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 at 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 at lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140323/bf670969/attachment-0001.html>

kevin sullivan

2014-03-24 16:04:51 UTC

Permalink

Thanks for the response Jakub!

I couldn't run your command exactly because I don't use the start_tls
command, I run everything over ldaps. I was able to bind anonymously using
this command:

# ldapsearch -H "ldaps://test-server/" -b
"uid=jharden,ou=Users,dc=example,dc=com"

I can even bind as the user using this command:

# ldapsearch -H "ldaps://test-server/" -b
"uid=jharden,ou=Users,dc=example,dc=com" -D
"uid=jharden,ou=Users,dc=example,dc=com" -W

I remade my CA, my server certificate, and my client certificate to make
sure that I wasn't screwing something up with the certificates. Things
still work with ldapsearch, but not with sssd.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140324/f64cdc8e/attachment.html>

Lukas Slebodnik

2014-03-24 16:46:47 UTC

Permalink

Post by kevin sullivan
Thanks for the response Jakub!
I couldn't run your command exactly because I don't use the start_tls
command, I run everything over ldaps. I was able to bind anonymously using
# ldapsearch -H "ldaps://test-server/" -b
"uid=jharden,ou=Users,dc=example,dc=com"
# ldapsearch -H "ldaps://test-server/" -b
"uid=jharden,ou=Users,dc=example,dc=com" -D
"uid=jharden,ou=Users,dc=example,dc=com" -W
I remade my CA, my server certificate, and my client certificate to make
sure that I wasn't screwing something up with the certificates. Things
still work with ldapsearch, but not with sssd.

I checked source code of libldap (which is used by sssd)
and return code 49 (0x31 LDAP_INVALID_CREDENTIALS) is return only if there is
problem with certificate.

sh-4.2$ grep -RniI -B2 LDAP_INVALID_CREDENTIALS
openldap-2.4.39/include/ldap.h-607-#define LDAP_X_PROXY_AUTHZ_FAILURE 0x2F /* LDAPv3 proxy authorization */
openldap-2.4.39/include/ldap.h-608-#define LDAP_INAPPROPRIATE_AUTH 0x30
openldap-2.4.39/include/ldap.h:609:#define LDAP_INVALID_CREDENTIALS 0x31
--
openldap-2.4.39/libraries/libldap/error.c-71-
openldap-2.4.39/libraries/libldap/error.c-72- C(LDAP_INAPPROPRIATE_AUTH, N_("Inappropriate authentication"));
openldap-2.4.39/libraries/libldap/error.c:73: C(LDAP_INVALID_CREDENTIALS, N_("Invalid credentials"));
--
openldap-2.4.39/libraries/libldap/tls_m.c-2744-
openldap-2.4.39/libraries/libldap/tls_m.c-2745- cert = SSL_LocalCertificate( s );
openldap-2.4.39/libraries/libldap/tls_m.c:2746: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap/tls_m.c-2759-
openldap-2.4.39/libraries/libldap/tls_m.c-2760- cert = SSL_PeerCertificate( s );
openldap-2.4.39/libraries/libldap/tls_m.c:2761: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap_r/error.c-71-
openldap-2.4.39/libraries/libldap_r/error.c-72- C(LDAP_INAPPROPRIATE_AUTH, N_("Inappropriate authentication"));
openldap-2.4.39/libraries/libldap_r/error.c:73: C(LDAP_INVALID_CREDENTIALS, N_("Invalid credentials"));
--
openldap-2.4.39/libraries/libldap_r/tls_m.c-2744-
openldap-2.4.39/libraries/libldap_r/tls_m.c-2745- cert = SSL_LocalCertificate( s );
openldap-2.4.39/libraries/libldap_r/tls_m.c:2746: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap_r/tls_m.c-2759-
openldap-2.4.39/libraries/libldap_r/tls_m.c-2760- cert = SSL_PeerCertificate( s );
openldap-2.4.39/libraries/libldap_r/tls_m.c:2761: if (!cert) return LDAP_INVALID_CREDENTIALS;

LS

Sumit Bose

2014-03-24 17:45:38 UTC

Permalink

Post by Lukas Slebodnik

I checked source code of libldap (which is used by sssd)
and return code 49 (0x31 LDAP_INVALID_CREDENTIALS) is return only if there is
problem with certificate.
sh-4.2$ grep -RniI -B2 LDAP_INVALID_CREDENTIALS
openldap-2.4.39/include/ldap.h-607-#define LDAP_X_PROXY_AUTHZ_FAILURE 0x2F /* LDAPv3 proxy authorization */
openldap-2.4.39/include/ldap.h-608-#define LDAP_INAPPROPRIATE_AUTH 0x30
openldap-2.4.39/include/ldap.h:609:#define LDAP_INVALID_CREDENTIALS 0x31
--
openldap-2.4.39/libraries/libldap/error.c-71-
openldap-2.4.39/libraries/libldap/error.c-72- C(LDAP_INAPPROPRIATE_AUTH, N_("Inappropriate authentication"));
openldap-2.4.39/libraries/libldap/error.c:73: C(LDAP_INVALID_CREDENTIALS, N_("Invalid credentials"));
--
openldap-2.4.39/libraries/libldap/tls_m.c-2744-
openldap-2.4.39/libraries/libldap/tls_m.c-2745- cert = SSL_LocalCertificate( s );
openldap-2.4.39/libraries/libldap/tls_m.c:2746: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap/tls_m.c-2759-
openldap-2.4.39/libraries/libldap/tls_m.c-2760- cert = SSL_PeerCertificate( s );
openldap-2.4.39/libraries/libldap/tls_m.c:2761: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap_r/error.c-71-
openldap-2.4.39/libraries/libldap_r/error.c-72- C(LDAP_INAPPROPRIATE_AUTH, N_("Inappropriate authentication"));
openldap-2.4.39/libraries/libldap_r/error.c:73: C(LDAP_INVALID_CREDENTIALS, N_("Invalid credentials"));
--
openldap-2.4.39/libraries/libldap_r/tls_m.c-2744-
openldap-2.4.39/libraries/libldap_r/tls_m.c-2745- cert = SSL_LocalCertificate( s );
openldap-2.4.39/libraries/libldap_r/tls_m.c:2746: if (!cert) return LDAP_INVALID_CREDENTIALS;
--
openldap-2.4.39/libraries/libldap_r/tls_m.c-2759-
openldap-2.4.39/libraries/libldap_r/tls_m.c-2760- cert = SSL_PeerCertificate( s );
openldap-2.4.39/libraries/libldap_r/tls_m.c:2761: if (!cert) return LDAP_INVALID_CREDENTIALS;

The server can return LDAP_INVALID_CREDENTIALS as well. I think there
might be an issue with the password. According to the logs your password
has 13 characters, does this make sense?

You PAM configuration is a bit unusual, because you have pam_sss first
and the pam_unix. Can you try to switch the order?

On my system it looks a bit like:

auth required pam_env.so
auth sufficient pam_unix.so nullok try_first_pass
auth requisite pam_succeed_if.so uid >= 1000 quiet_success
auth sufficient pam_sss.so use_first_pass
auth required pam_deny.so

If this works there might be an issue when SSSD is first in the stack
and has to read the password.

HTH

bye,
Sumit

Post by Lukas Slebodnik
LS
_______________________________________________
sssd-users mailing list
sssd-users at lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

kevin sullivan

2014-03-24 22:25:36 UTC

Permalink

Lukas and Sumit, thanks for your responses.

According to the logs your password has
13 characters, does this make sense?

No, my password doesn't have 13 characters. I did notice that no matter
what I typed, the authtok size was always 13.

You PAM configuration is a bit unusual,
because you have pam_sss first and the
pam_unix. Can you try to switch the order?

I changed my pam configuration. Also, I removed the 'access_provider' and
'ldap_access_filter' options just in case. I also tried changing from
'ldaps' to 'ldap + start_tls'. None of these seemed to fix the problem. I
have a ton of log output from sssd and my ldap server, would it help if I
posted some of the output?

On the ldap server side, I don't see any errors that are out of the
ordinary. I believe when it is reading password policy objects I see some
errors on the server side saying:

......INC
0030: 4f 52 52 45 43 54 a0 1d 30 1b 04 19 31 2e 33 2e
ORRECT..0...1.3.
0040: 36 2e 31 2e 34 2e 31 2e 34 32 2e 32 2e 32 37 2e
6.1.4.1.42.2.27.
0050: 38 2e 35 2e 31
8.5.1

But I have removed password policy before and seen no improvements.

return code 49 (0x31 LDAP_INVALID_CREDENTIALS)
is return only if there is problem with certificate.

I agree that it could be a certificate problem, but the server side doesn't
seem to display any errors about certificates and sssd doesn't complain
(other than the error 49). I am able to use the same certificates with
ldapsearch. I changed both the client and server side to demand
certificates (ldap.conf and slapd.conf) and ldapsearch still works. I am
fairly confident in the certificates that I made today. I followed this
tutorial (
http://spectlog.com/content/Create_Certificate_Authority_(CA)_instead_of_using_self-signed_Certificates)
and made a CA and then signed two certificates with that CA.

Thanks for all the help so far!

Kevin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140324/dad9eb33/attachment.html>

Sumit Bose

2014-03-25 09:02:08 UTC

Permalink

Post by kevin sullivan
Lukas and Sumit, thanks for your responses.

According to the logs your password has
13 characters, does this make sense?

No, my password doesn't have 13 characters. I did notice that no matter
what I typed, the authtok size was always 13.

That's odd. Which version of SSSD are you using on which platform?

Can you use strace to trace the authentication process form the sshd
side? Some thing like

strace -o /tmp/strace.out -s 256 -p PID_of_the_main_sshd_process

should work.

The output will contain your password, please send the file to me
directly and not to the list. From the output I would be able to see if
the 13 character password is send to SSSD already from the sshd.

bye,
Sumit

kevin sullivan

2014-03-25 14:16:52 UTC

Permalink

Post by Sumit Bose
That's odd. Which version of SSSD are you using on which platform?

I am using sssd-1.9.2-82.el6. I am running rhel 6.4. I can't budge on the
OS, but I can update the RPM if necessary.

Post by Sumit Bose
Can you use strace to trace the authentication process form the sshd
side? Some thing like
strace -o /tmp/strace.out -s 256 -p PID_of_the_main_sshd_process

You mean the main sshd process correct? Not the ssh process that I create
when I try to ssh as my user?

root 25000 1 0 14:00 ? 00:00:00 /usr/sbin/sshd

I ran the strace and I will send that to you very soon.

Thanks,

Kevin

Post by Sumit Bose

Post by kevin sullivan
Lukas and Sumit, thanks for your responses.

According to the logs your password has
13 characters, does this make sense?

No, my password doesn't have 13 characters. I did notice that no matter
what I typed, the authtok size was always 13.

That's odd. Which version of SSSD are you using on which platform?
Can you use strace to trace the authentication process form the sshd
side? Some thing like
strace -o /tmp/strace.out -s 256 -p PID_of_the_main_sshd_process
should work.
The output will contain your password, please send the file to me
directly and not to the list. From the output I would be able to see if
the 13 character password is send to SSSD already from the sshd.
bye,
Sumit
_______________________________________________
sssd-users mailing list
sssd-users at lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140325/123a4523/attachment.html>

kevin sullivan

2014-03-26 15:04:11 UTC

Permalink

Want to say thanks for all the help! I finally found my problem, I needed
to have 'nss' listed as one of my 'services' in the 'sssd' section of
/etc/sssd/sssd.conf. At some point, I removed that service from the list
and that seems to be very very bad.

[sssd]
services = pam, nss

Now I can read ldap user information via 'getent passwd user' and I can ssh
via 'ssh user at server'.

Thank you again for all of the help!

On Tue, Mar 25, 2014 at 10:16 AM, kevin sullivan

Post by kevin sullivan

Post by Sumit Bose
That's odd. Which version of SSSD are you using on which platform?

I am using sssd-1.9.2-82.el6. I am running rhel 6.4. I can't budge on the
OS, but I can update the RPM if necessary.

Post by Sumit Bose
Can you use strace to trace the authentication process form the sshd
side? Some thing like
strace -o /tmp/strace.out -s 256 -p PID_of_the_main_sshd_process

You mean the main sshd process correct? Not the ssh process that I create
when I try to ssh as my user?
root 25000 1 0 14:00 ? 00:00:00 /usr/sbin/sshd
I ran the strace and I will send that to you very soon.
Thanks,
Kevin

Post by Sumit Bose

Post by kevin sullivan
Lukas and Sumit, thanks for your responses.

According to the logs your password has
13 characters, does this make sense?

No, my password doesn't have 13 characters. I did notice that no matter
what I typed, the authtok size was always 13.

That's odd. Which version of SSSD are you using on which platform?
Can you use strace to trace the authentication process form the sshd
side? Some thing like
strace -o /tmp/strace.out -s 256 -p PID_of_the_main_sshd_process
should work.
The output will contain your password, please send the file to me
directly and not to the list. From the output I would be able to see if
the 13 character password is send to SSSD already from the sshd.
bye,
Sumit
_______________________________________________
sssd-users mailing list
sssd-users at lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140326/2a98abf7/attachment.html>