2:01 p.m.
Hello,
We are attempting to get LDAP logins set up with sssd on RHEL 7.6.
sssd is able to look up the user against the backend LDAP using a secure connection on
port 636. However, it does not attempt to authenticate.
We think pam authentication is not getting called for remote logins. Local logins are
working.
On the ldap server, we can see the search but not an authentication attempt.
In case it matters: We don't store the POSIX uid in LDAP.
Where should we look for the missing setting(s)? Some log snips follow.
In /var/log/secure on the client vm, we see:
Aug 8 16:45:32 clientvm polkitd[5652]: Registered Authentication Agent for
unix-process:8478:2629285 (system bus name :1.92 [/usr/bin/pkttyagent --notify-fd 5
--fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale
en_US.UTF-8)
Aug 8 16:45:32 clientvm polkitd[5652]: Unregistered Authentication Agent for
unix-process:8478:2629285 (system bus name :1.92, object path
/org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from
bus)
Aug 8 16:45:53 clientvm unix_chkpwd[8491]: password check failed for user (myuser)
Aug 8 16:45:53 clientvm sshd[8489]: pam_unix(sshd:auth): authentication failure; logname=
uid=0 euid=0 tty=ssh ruser= rhost=REDACTED user=myuser
Aug 8 16:45:53 clientvm sshd[8489]: pam_sss(sshd:auth): authentication failure; logname=
uid=0 euid=0 tty=ssh ruser= rhost=REDACTED user=myuser
Aug 8 16:45:53 clientvm sshd[8489]: pam_sss(sshd:auth): received for user myuser: 10
(User not known to the underlying authentication module)
Aug 8 16:45:55 clientvm sshd[8489]: Failed password for myuser from REDACTED port 10320
ssh2
Aug 8 16:46:07 clientvm sshd[8489]: Connection closed by REDACTED port 10320 [preauth]
In /var/log/sssd/sssd_mydomain.log:
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_get_account_info_handler] (0x0200):
Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sss_domain_get_state] (0x1000): Domain
mydomain is Active
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x561aa191ac20
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x561aa191ace0
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Running timer event
0x561aa191ac20 "ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Destroying timer event
0x561aa191ace0 "ltdb_timeout"
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Ending timer event
0x561aa191ac20 "ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_attach_req] (0x0400): DP Request
[Initgroups #2]: New request. Flags [0x0001].
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_attach_req] (0x0400): Number of active
DP request: 1
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sss_domain_get_state] (0x1000): Domain
mydomain is Active
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_send] (0x4000):
Retrieving info for initgroups call
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_next_base] (0x0400):
Searching for users with base [ou=people,ou=primary,ou=eid,dc=my,dc=edu]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_print_server] (0x2000): Searching
REDACTED:636
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=myuser)(objectclass=inetorgperson)(&(uid=*)(!(uid=0))))][ou=people,ou=primary,ou=eid,dc=my,dc=edu].
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [objectClass]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uid]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userPassword]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uid]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gidNumber]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gecos]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [homeDirectory]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginShell]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPrincipalName]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [cn]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [modifyTimestamp]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [modifyTimestamp]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowLastChange]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMin]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMax]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowWarning]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowInactive]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowExpire]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowFlag]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbLastPwdChange]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPasswordExpiration]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [pwdAttribute]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [authorizedService]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [accountExpires]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userAccountControl]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [nsAccountLock]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [host]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [rhost]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginDisabled]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginExpirationTime]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [sshPublicKey]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userCertificate;binary]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [mail]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x2000):
ldap_search_ext called, msgid = 5
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_op_add] (0x2000): New operation 5
timeout 6
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000): Trace:
sh[0x561aa17fdf50], connected[1], ops[0x561aa191d380], ldap[0x561aa17dbd00]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_message] (0x4000): Message
type: [LDAP_RES_SEARCH_ENTRY]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_entry] (0x1000): OriginalDN:
[uid=myuser,ou=people,ou=primary,ou=eid,dc=my,dc=edu].
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [mail]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [uid]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectClass]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [modifyTimestamp]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000): Trace:
sh[0x561aa17fdf50], connected[1], ops[0x561aa191d380], ldap[0x561aa17dbd00]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_message] (0x4000): Message
type: [LDAP_RES_SEARCH_RESULT]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_op_finished] (0x0400):
Search result: Success(0), no errmsg set
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_op_destructor] (0x2000): Operation 5
finished
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_user] (0x4000): Receiving
info for the user
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): start ldb transaction
(nesting: 0)
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_user] (0x4000): Storing
the user
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0400): Save user
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_attrs_get_sid_str] (0x1000): No
[objectSID] attribute. [0][Success]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x4000): objectSID: not
available for user
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x4000): Failed to
retrieve UUID [2][No such file or directory].
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_primary_name] (0x0400):
Processing object myuser
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0400): Processing user
myuser@mydomain
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Cannot retrieve
UID for [myuser@mydomain] in domain [mydomain].
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Failed to save
user [myuser@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): cancel ldb transaction
(nesting: 0)
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_id_op_done] (0x4000): releasing
operation connection
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_done] (0x0400): DP Request
[Initgroups #2]: Request handler finished [0]: Success
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [_dp_req_recv] (0x0400): DP Request
[Initgroups #2]: Receiving request data.
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_reply_list_success] (0x0400): DP
Request [Initgroups #2]: Finished. Success.
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_reply_std] (0x1000): DP Request
[Initgroups #2]: Returning [Internal Error]: 3,1432158246,Init group lookup failed
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::mydomain:name=myuser@mydomain] from reply table
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_destructor] (0x0400): DP Request
[Initgroups #2]: Request removed.
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000): Trace:
sh[0x561aa17fdf50], connected[1], ops[(nil)], ldap[0x561aa17dbd00]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000): Trace: end
of ldap_result list
in /var/log/sssd/sssd_pam.log:
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering
pam_cmd_authenticate
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser' matched without domain, user is myuser
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): command:
SSS_PAM_AUTHENTICATE
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: REDACTED
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 8489
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_initgr_check_timeout] (0x4000): User [myuser]
not found in PAM cache.
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR #0: Setting
"Initgroups by name" plugin
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #0: New request
'Initgroups by name'
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #0: Parsing
input name [myuser]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser' matched without domain, user is myuser
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #0: Setting name
[myuser]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #0:
Performing a multi-domain search
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #0: Search
will bypass the cache and check the data provider
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_validate_domain_type] (0x2000): Request
type POSIX-only for domain mydomain type POSIX is valid
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #0: Using
domain [mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #0:
Preparing input data for domain [mydomain] rules
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #0: Looking up
myuser@mydomain
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: Checking
negative cache for [myuser@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative
cache for [NCE/USER/mydomain/myuser@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0:
[myuser@mydomain] is not present in negative cache
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #0: Looking up
[myuser@mydomain] in data provider
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request
for [0x5624540cd550:3:myuser@mydomain@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request
for [mydomain][0x3][BE_REQ_INITGROUPS][name=myuser@mydomain:-]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562454f181e0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering
request [0x5624540cd550:3:myuser@mydomain@mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x562454f181e0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn:
0x562454f1bc40
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data
Provider - DP error code: 3 errno: 1432158246 error message: Init group lookup failed
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_common_dp_recv] (0x0040): CR #0: Data
Provider Error: 3, 1432158246, Init group lookup failed
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_common_dp_recv] (0x0400): CR #0: Due to
an error we will return cached data
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Looking
up [myuser@mydomain] in cache
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f289b0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f28a70
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x562454f289b0
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f28a70 "ltdb_timeout"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x562454f289b0
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Object
[myuser@mydomain] was not found in cache
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_process_result] (0x0400): CR #0:
Finished: Not found
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f1d530
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f20ff0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x562454f1d530
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f20ff0 "ltdb_timeout"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x562454f1d530
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result
[10]: User not known to the underlying authentication module.
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f29580
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f29640
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x562454f29580
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f29640 "ltdb_timeout"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x562454f29580
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f248b0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f23ec0
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x562454f248b0
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f23ec0 "ltdb_timeout"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x562454f248b0
"ltdb_callback"
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter]
not available, not fatal.
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request:
[0x5624540cd550:3:myuser@mydomain@mydomain]
(Thu Aug 8 16:46:07 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Thu Aug 8 16:46:07 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client
[0x562454f245a0][19]
Thanks,
Jane
2:12 p.m.
New subject: Problem getting sssd to work with LDAP authentication
What does your LDAP domain section look like and why are you not using the POSIX object
class for uids?
> On August 9, 2019 at 12:01 PM Jane Eason <jeason(a)gsu.edu> wrote:
>
>
> Hello,
>
> We are attempting to get LDAP logins set up with sssd on RHEL 7.6.
>
> sssd is able to look up the user against the backend LDAP using a secure connection
on port 636. However, it does not attempt to authenticate.
> We think pam authentication is not getting called for remote logins. Local logins are
working.
>
> On the ldap server, we can see the search but not an authentication attempt.
>
> In case it matters: We don't store the POSIX uid in LDAP.
>
> Where should we look for the missing setting(s)? Some log snips follow.
>
> In /var/log/secure on the client vm, we see:
>
> Aug 8 16:45:32 clientvm polkitd[5652]: Registered Authentication Agent for
unix-process:8478:2629285 (system bus name :1.92 [/usr/bin/pkttyagent --notify-fd 5
--fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale
en_US.UTF-8)
> Aug 8 16:45:32 clientvm polkitd[5652]: Unregistered Authentication Agent for
unix-process:8478:2629285 (system bus name :1.92, object path
/org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from
bus)
> Aug 8 16:45:53 clientvm unix_chkpwd[8491]: password check failed for user (myuser)
> Aug 8 16:45:53 clientvm sshd[8489]: pam_unix(sshd:auth): authentication failure;
logname= uid=0 euid=0 tty=ssh ruser= rhost=REDACTED user=myuser
> Aug 8 16:45:53 clientvm sshd[8489]: pam_sss(sshd:auth): authentication failure;
logname= uid=0 euid=0 tty=ssh ruser= rhost=REDACTED user=myuser
> Aug 8 16:45:53 clientvm sshd[8489]: pam_sss(sshd:auth): received for user myuser: 10
(User not known to the underlying authentication module)
> Aug 8 16:45:55 clientvm sshd[8489]: Failed password for myuser from REDACTED port
10320 ssh2
> Aug 8 16:46:07 clientvm sshd[8489]: Connection closed by REDACTED port 10320
[preauth]
>
> In /var/log/sssd/sssd_mydomain.log:
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_get_account_info_handler]
(0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sss_domain_get_state] (0x1000):
Domain mydomain is Active
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x561aa191ac20
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x561aa191ace0
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Running timer event
0x561aa191ac20 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Destroying timer
event 0x561aa191ace0 "ltdb_timeout"
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): Ending timer event
0x561aa191ac20 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_attach_req] (0x0400): DP Request
[Initgroups #2]: New request. Flags [0x0001].
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_attach_req] (0x0400): Number of
active DP request: 1
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sss_domain_get_state] (0x1000):
Domain mydomain is Active
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_send] (0x4000):
Retrieving info for initgroups call
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_next_base] (0x0400):
Searching for users with base [ou=people,ou=primary,ou=eid,dc=my,dc=edu]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_print_server] (0x2000):
Searching REDACTED:636
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(uid=myuser)(objectclass=inetorgperson)(&(uid=*)(!(uid=0))))][ou=people,ou=primary,ou=eid,dc=my,dc=edu].
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [objectClass]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uid]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userPassword]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uid]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gidNumber]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gecos]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [homeDirectory]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginShell]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPrincipalName]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [cn]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [modifyTimestamp]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [modifyTimestamp]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowLastChange]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMin]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMax]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowWarning]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowInactive]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowExpire]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowFlag]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbLastPwdChange]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPasswordExpiration]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [pwdAttribute]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [authorizedService]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [accountExpires]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userAccountControl]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [nsAccountLock]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [host]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [rhost]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginDisabled]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginExpirationTime]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginAllowedTimeMap]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [sshPublicKey]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userCertificate;binary]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [mail]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_ext_step] (0x2000):
ldap_search_ext called, msgid = 5
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_op_add] (0x2000): New operation
5 timeout 6
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000):
Trace: sh[0x561aa17fdf50], connected[1], ops[0x561aa191d380], ldap[0x561aa17dbd00]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_ENTRY]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_entry] (0x1000):
OriginalDN: [uid=myuser,ou=people,ou=primary,ou=eid,dc=my,dc=edu].
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [mail]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [uid]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectClass]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_parse_range] (0x2000): No
sub-attributes for [modifyTimestamp]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000):
Trace: sh[0x561aa17fdf50], connected[1], ops[0x561aa191d380], ldap[0x561aa17dbd00]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_RESULT]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_op_destructor] (0x2000):
Operation 5 finished
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_user] (0x4000):
Receiving info for the user
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): start ldb transaction
(nesting: 0)
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_initgr_user] (0x4000):
Storing the user
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0400): Save user
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_attrs_get_sid_str] (0x1000): No
[objectSID] attribute. [0][Success]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x4000): objectSID:
not available for user
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x4000): Failed to
retrieve UUID [2][No such file or directory].
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_get_primary_name] (0x0400):
Processing object myuser
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0400): Processing
user myuser@mydomain
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Cannot
retrieve UID for [myuser@mydomain] in domain [mydomain].
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Failed to
save user [myuser@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [ldb] (0x4000): cancel ldb
transaction (nesting: 0)
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_id_op_done] (0x4000): releasing
operation connection
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_done] (0x0400): DP Request
[Initgroups #2]: Request handler finished [0]: Success
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [_dp_req_recv] (0x0400): DP Request
[Initgroups #2]: Receiving request data.
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_reply_list_success] (0x0400):
DP Request [Initgroups #2]: Finished. Success.
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_reply_std] (0x1000): DP
Request [Initgroups #2]: Returning [Internal Error]: 3,1432158246,Init group lookup
failed
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::mydomain:name=myuser@mydomain] from reply table
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_destructor] (0x0400): DP
Request [Initgroups #2]: Request removed.
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [dp_req_destructor] (0x0400): Number
of active DP request: 0
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000):
Trace: sh[0x561aa17fdf50], connected[1], ops[(nil)], ldap[0x561aa17dbd00]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
>
>
> in /var/log/sssd/sssd_pam.log:
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering
pam_cmd_authenticate
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser' matched without domain, user is myuser
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): command:
SSS_PAM_AUTHENTICATE
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: REDACTED
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 8489
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_initgr_check_timeout] (0x4000): User
[myuser] not found in PAM cache.
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR #0:
Setting "Initgroups by name" plugin
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #0: New request
'Initgroups by name'
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #0:
Parsing input name [myuser]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name
'myuser' matched without domain, user is myuser
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #0: Setting
name [myuser]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #0:
Performing a multi-domain search
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #0:
Search will bypass the cache and check the data provider
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain mydomain type POSIX is valid
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #0: Using
domain [mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR
#0: Preparing input data for domain [mydomain] rules
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #0:
Looking up myuser@mydomain
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0:
Checking negative cache for [myuser@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/USER/mydomain/myuser@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0:
[myuser@mydomain] is not present in negative cache
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #0: Looking
up [myuser@mydomain] in data provider
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing
request for [0x5624540cd550:3:myuser@mydomain@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating
request for [mydomain][0x3][BE_REQ_INITGROUPS][name=myuser@mydomain:-]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562454f181e0
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering
request [0x5624540cd550:3:myuser@mydomain@mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_remove_timeout] (0x2000):
0x562454f181e0
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn:
0x562454f1bc40
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from
Data Provider - DP error code: 3 errno: 1432158246 error message: Init group lookup
failed
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_common_dp_recv] (0x0040): CR #0:
Data Provider Error: 3, 1432158246, Init group lookup failed
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_common_dp_recv] (0x0400): CR #0:
Due to an error we will return cached data
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0:
Looking up [myuser@mydomain] in cache
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f289b0
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f28a70
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event
0x562454f289b0 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f28a70 "ltdb_timeout"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event
0x562454f289b0 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0:
Object [myuser@mydomain] was not found in cache
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [cache_req_process_result] (0x0400): CR #0:
Finished: Not found
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f1d530
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f20ff0
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event
0x562454f1d530 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f20ff0 "ltdb_timeout"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event
0x562454f1d530 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with
result [10]: User not known to the underlying authentication module.
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f29580
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f29640
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event
0x562454f29580 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f29640 "ltdb_timeout"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event
0x562454f29580 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x562454f248b0
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x562454f23ec0
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event
0x562454f248b0 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event
0x562454f23ec0 "ltdb_timeout"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event
0x562454f248b0 "ltdb_callback"
>
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [filter_responses] (0x0100):
[pam_response_filter] not available, not fatal.
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
> (Thu Aug 8 16:45:53 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting
request: [0x5624540cd550:3:myuser@mydomain@mydomain]
> (Thu Aug 8 16:46:07 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
> (Thu Aug 8 16:46:07 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client
[0x562454f245a0][19]
>
> Thanks,
>
> Jane
> _______________________________________________
> sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
> Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahoste...
3:33 p.m.
New subject: Problem getting sssd to work with LDAP authentication
Our LDAP does not include the POSIX schema, so we made a couple of entries in sssd.conf to
attempt to work around that.
Here is our complete (slightly redacted) sssd.conf:
[domain/mydomain]
id_provider = ldap
auth_provider = ldap
access_provider = ldap
ldap_uri = ldaps://mydomain.my.edu
ldap_search_base = ou=people,ou=primary,ou=eid,dc=my,dc=edu
ldap_default_bind_dn = cn=my-proxy,ou=proxies,dc=my,dc=edu
ldap_default_authtok = REDACTED
ldap_access_filter = uid=*
ldap_schema = rfc2307
cache_credentials = false
ldap_user_object_class = inetorgperson
ldap_id_mapping = false
ldap_user_uid_number = uid
#proxy_pam_target = sssd-shadowutils
ldap_id_use_start_tls = false
ldap_tls_cacertdir = /etc/openldap/cacerts
ldap_tls_cacert = /etc/openldap/cacerts/mydomain_my_edu_interm.cer
ldap_tls_cert = /etc/openldap/certs/mydomain_my_edu_cert.cer
ldap_tls_reqcert = never
entry_cache_timeout = 5
debug_level = 9
[sssd]
config_file_version = 2
reconnection_retries = 3
sbus_timeout = 30
services = nss, pam
domains = mydomain
debug_level = 9
certificate_verification = no_verification
[pam]
reconnection_retries = 3
offline_credentials_expiration = 2
offline_failed_login_attempts = 3
offline_failed_login_delay = 5
pam_verbosity = 3
debug_level = 9
[nss]
filter_groups = root
filter_users = root
reconnection_retries = 3
debug_level = 9
Thanks for looking,
Jane
2:34 a.m.
New subject: Problem getting sssd to work with LDAP authentication
On Fri, Aug 09, 2019 at 08:33:43PM -0000, Jane Eason wrote:
Our LDAP does not include the POSIX schema, so we made a couple of
entries in sssd.conf to attempt to work around that.
Here is our complete (slightly redacted) sssd.conf:
[domain/mydomain]
id_provider = ldap
auth_provider = ldap
access_provider = ldap
ldap_uri = ldaps://mydomain.my.edu
ldap_search_base = ou=people,ou=primary,ou=eid,dc=my,dc=edu
ldap_default_bind_dn = cn=my-proxy,ou=proxies,dc=my,dc=edu
ldap_default_authtok = REDACTED
ldap_access_filter = uid=*
ldap_schema = rfc2307
cache_credentials = false
ldap_user_object_class = inetorgperson
ldap_id_mapping = false
ldap_user_uid_number = uid
Hi,
according to the logs you have send the uid attribute already is used
for the user name (uid=myuser) so it cannot but the numerical POSIX UID
at the same time. Please check if the attribute with the UID has a
different name.
HTH
bye,
Sumit
> #proxy_pam_target = sssd-shadowutils
> ldap_id_use_start_tls = false
> ldap_tls_cacertdir = /etc/openldap/cacerts
> ldap_tls_cacert = /etc/openldap/cacerts/mydomain_my_edu_interm.cer
> ldap_tls_cert = /etc/openldap/certs/mydomain_my_edu_cert.cer
> ldap_tls_reqcert = never
> entry_cache_timeout = 5
> debug_level = 9
>
>
> [sssd]
> config_file_version = 2
> reconnection_retries = 3
> sbus_timeout = 30
> services = nss, pam
> domains = mydomain
> debug_level = 9
> certificate_verification = no_verification
>
> [pam]
> reconnection_retries = 3
> offline_credentials_expiration = 2
> offline_failed_login_attempts = 3
> offline_failed_login_delay = 5
> pam_verbosity = 3
> debug_level = 9
>
> [nss]
> filter_groups = root
> filter_users = root
> reconnection_retries = 3
> debug_level = 9
>
> Thanks for looking,
>
> Jane
> _______________________________________________
> sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
> Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahoste...
2:55 a.m.
New subject: Problem getting sssd to work with LDAP authentication
On Fri, Aug 09, 2019 at 08:33:43PM -0000, Jane Eason wrote:
Our LDAP does not include the POSIX schema, so we made a couple of
entries in sssd.conf to attempt to work around that.
Here is our complete (slightly redacted) sssd.conf:
[domain/mydomain]
id_provider = ldap
auth_provider = ldap
access_provider = ldap
ldap_uri = ldaps://mydomain.my.edu
ldap_search_base = ou=people,ou=primary,ou=eid,dc=my,dc=edu
ldap_default_bind_dn = cn=my-proxy,ou=proxies,dc=my,dc=edu
ldap_default_authtok = REDACTED
ldap_access_filter = uid=*
ldap_schema = rfc2307
cache_credentials = false
ldap_user_object_class = inetorgperson
ldap_id_mapping = false
ldap_user_uid_number = uid
Are you sure your user ID are stored in the uid attribute? Because in
the earlier log snippet, sdap_save_user was complaining about missing
UID:
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Cannot retrieve
UID for [myuser@mydomain] in domain [mydomain]
(Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Failed to save
user [myuser@mydomain]
9:11 a.m.
New subject: Problem getting sssd to work with LDAP authentication
[(&(uid=myuser)(objectclass=inetorgperson)(&(uid=*)(!(uid=0))))][ou=people,ou=primary,ou=eid,dc=my,dc=edu].
what does an ldapsearch with objectclass=inetorgperson uid=\* return? and do you also have
a uidnumber attribute?
> On August 12, 2019 at 12:55 AM Jakub Hrozek <jhrozek(a)redhat.com> wrote:
>
>
> On Fri, Aug 09, 2019 at 08:33:43PM -0000, Jane Eason wrote:
> > Our LDAP does not include the POSIX schema, so we made a couple of entries in
sssd.conf to attempt to work around that.
> >
> > Here is our complete (slightly redacted) sssd.conf:
> >
> > [domain/mydomain]
> > id_provider = ldap
> > auth_provider = ldap
> > access_provider = ldap
> > ldap_uri = ldaps://mydomain.my.edu
> > ldap_search_base = ou=people,ou=primary,ou=eid,dc=my,dc=edu
> > ldap_default_bind_dn = cn=my-proxy,ou=proxies,dc=my,dc=edu
> > ldap_default_authtok = REDACTED
> > ldap_access_filter = uid=*
> > ldap_schema = rfc2307
> > cache_credentials = false
> > ldap_user_object_class = inetorgperson
> > ldap_id_mapping = false
> > ldap_user_uid_number = uid
>
> Are you sure your user ID are stored in the uid attribute? Because in
> the earlier log snippet, sdap_save_user was complaining about missing
> UID:
>
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Cannot
retrieve UID for [myuser@mydomain] in domain [mydomain]
> (Thu Aug 8 16:45:53 2019) [sssd[be[mydomain]]] [sdap_save_user] (0x0020): Failed to
save user [myuser@mydomain]
> _______________________________________________
> sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
> Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahoste...
2:21 p.m.
New subject: Problem getting sssd to work with LDAP authentication
We do not have the uid number in LDAP.
In our LDAP uid is the username, so LDAP has e.g. uid=bob. There is a local Linux user
named "bob" as well (we are not creating accounts on login).
We thought we could get around having to have the uid number in LDAP, using the following
line in sssd.conf:
ldap_user_uid_number = uid
so at least the ldap query would return something.
When "bob" tries to login we do see bob's attributes returned from the sssd
ldap query, but it stops there without any attempt at an LDAP bind from bob.
Here is the result of an ldapsearch with objectclass=inetorgperson uid=\*
dn: uid=bob,ou=people,ou=primary,ou=eid,dc=my,dc=edu
mail: bob(a)my.edu
uid: bob
initials: B
givenName: Bob
sn: Barker
objectClass: inetOrgPerson
objectClass: myPerson
objectClass: eduPerson
objectClass: organizationalPerson
objectClass: Person
objectClass: ndsLoginProperties
objectClass: Top
Thanks,
Jane
3:14 p.m.
New subject: Problem getting sssd to work with LDAP authentication
I'm just going to leave this here:
Read RFC 2307 and pay attention to section 5.2. Affected library functions.
Good luck!
> On August 12, 2019 at 12:21 PM Jane Eason <jeason(a)gsu.edu> wrote:
>
>
> We do not have the uid number in LDAP.
>
> In our LDAP uid is the username, so LDAP has e.g. uid=bob. There is a local Linux
user named "bob" as well (we are not creating accounts on login).
>
> We thought we could get around having to have the uid number in LDAP, using the
following line in sssd.conf:
>
> ldap_user_uid_number = uid
>
> so at least the ldap query would return something.
>
> When "bob" tries to login we do see bob's attributes returned from the
sssd ldap query, but it stops there without any attempt at an LDAP bind from bob.
>
> Here is the result of an ldapsearch with objectclass=inetorgperson uid=\*
>
> dn: uid=bob,ou=people,ou=primary,ou=eid,dc=my,dc=edu
> mail: bob(a)my.edu
> uid: bob
> initials: B
> givenName: Bob
> sn: Barker
> objectClass: inetOrgPerson
> objectClass: myPerson
> objectClass: eduPerson
> objectClass: organizationalPerson
> objectClass: Person
> objectClass: ndsLoginProperties
> objectClass: Top
>
> Thanks,
>
> Jane
> _______________________________________________
> sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
> Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahoste...
2:12 a.m.
New subject: Problem getting sssd to work with LDAP authentication
On Mon, Aug 12, 2019 at 07:21:15PM -0000, Jane Eason wrote:
We do not have the uid number in LDAP.
In our LDAP uid is the username, so LDAP has e.g. uid=bob. There is a local Linux user
named "bob" as well (we are not creating accounts on login).
We thought we could get around having to have the uid number in LDAP, using the following
line in sssd.conf:
ldap_user_uid_number = uid
so at least the ldap query would return something.
When "bob" tries to login we do see bob's attributes returned from the sssd
ldap query, but it stops there without any attempt at an LDAP bind from bob.
Here is the result of an ldapsearch with objectclass=inetorgperson uid=\*
dn: uid=bob,ou=people,ou=primary,ou=eid,dc=my,dc=edu
mail: bob(a)my.edu
uid: bob
initials: B
givenName: Bob
sn: Barker
objectClass: inetOrgPerson
objectClass: myPerson
objectClass: eduPerson
objectClass: organizationalPerson
objectClass: Person
objectClass: ndsLoginProperties
objectClass: Top
What is typically meant by UID in the sssd context is not the LDAP uid
attribute, but a numerical identifier (user-ID). It looks like your
entries in LDAP don't have them.
Typically what is done is that the entries also receive the posixAccount
objectclass and then you'd add a uidNumber and a gidNumber.
Without a UID number or a way to map the UID number with some other
means (right know that would be from a Windows SID), SSSD cannot resolve
those users.
(An exception is an application domain where you only use the LDAP users through
the D-Bus API by an app, but I'm guessing that's not what you are after)
1710
days inactive
1714
days old
sssd-users@lists.fedorahosted.org
8 comments
4 participants
participants (4)
-
Jakub Hrozek -
Jane Eason -
patrick.hush＠comcast.net -
Sumit Bose