[Freeipa-users] Unable to resolve AD users from IPA clients

Wed Jan 4 15:19:04 UTC 2017

Hi, 
thank you for help. 

I have tried to add 

subdomain_inherit = ignore_group_members 
ignore_group_members = True 

into sssd.conf on server but problem still persists. 

>By the way, did you install 7.3 cleanly or did you upgrade? 
It has been upgraded. 

>D id you ever removed the cache post-upgrade on the server? 
Yes I did it couple of times both on server and client 

I find out that when client return value from id it differ from id output on server: 

Client: 
id tst99655 at example.com 
uid=20018(tst99655 at cen.example.com) gid=5001(csunix) groups=5001(csunix) 

Server: 
uid=20018(tst99655 at cen.example.com) gid=5001(csunix) groups=5001(csunix),930000008(final_test_group) 
root at tidmipa01:~# 

Csunix group is in AD, final_test_group is group from IPA server. There is no 930000008(final_test_group) in output from client. 

This is log from client when the sss_cache is empty - no response: 

==> sssd_nss.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! 
... 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f864e2a6880:1:tst99655 at example.com@example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [example.com][0x1][BE_REQ_USER][1][name=tst99655 at example.com:-] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:tst99655 at example.com@example.com] 

==> sssd_vs.example.com.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=tst99655 at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): DP Request [Account #6]: New request. Flags [0x0001]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=tst99655))][cn=Default Trust View,cn=views,cn=accounts,dc=vs,dc=example,dc=cz]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_send] (0x0400): Executing extended operation 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_done] (0x0040): ldap_extended_operation result: No such object(32), (null). 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_get_user_done] (0x0040): s2n exop request failed. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_done] (0x0400): DP Request [Account #6]: Request handler finished [0]: Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #6]: Receiving request data. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #6]: Finished. Success. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #6]: Returning [Success]: 0,0,Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1::example.com:name=tst99655 at example.com] from reply table 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #6]: Request removed. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 

==> sssd_nss.log <== 
... 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f864e2a6880:1:tst99655 at example.com:U at vs.example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [vs.example.com][0x1][BE_REQ_USER][1][name=tst99655 at example.com:U] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:tst99655 at example.com:U at vs.example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:tst99655 at example.com@example.com] 

==> sssd_vs.example.com.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=tst99655 at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): DP Request [Account #7]: New request. Flags [0x0001]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=accounts,dc=vs,dc=example,dc=cz] 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(krbPrincipalName=tst99655 at example.com)(mail=tst99655 at example.com)(krbPrincipalName=tst99655\\@example.com at VS.EXAMPLE.COM))(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=vs,dc=example,dc=cz]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] 
... 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sdap_get_users_done] (0x0040): Failed to retrieve users [2][No such file or directory]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sysdb_search_by_name] (0x0400): No such entry 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [tst99655 at example.com] found. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_done] (0x0400): DP Request [Account #7]: Request handler finished [0]: Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #7]: Receiving request data. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #7]: Finished. Success. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #7]: Returning [Success]: 0,0,Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1:U:vs.example.com:name=tst99655 at example.com] from reply table 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #7]: Request removed. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 

==> sssd_nss.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f864e2a6880:1:tst99655 at example.com:U at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [example.com][0x1][BE_REQ_USER][1][name=tst99655 at example.com:U] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:tst99655 at example.com:U at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:tst99655 at example.com:U at vs.example.com] 

==> sssd_v.example.com.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=tst99655 at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): DP Request [Account #8]: New request. Flags [0x0001]. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_send] (0x0400): Executing extended operation 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_done] (0x0040): ldap_extended_operation result: No such object(32), (null). 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [ipa_s2n_get_user_done] (0x0040): s2n exop request failed. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_done] (0x0400): DP Request [Account #8]: Request handler finished [0]: Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #8]: Receiving request data. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #8]: Finished. Success. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #8]: Returning [Success]: 0,0,Success 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1:U:example.com:name=tst99655 at example.com] from reply table 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #8]: Request removed. 
(Wed Jan 4 15:21:22 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 
==> sssd_nss.log <== 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [tst99655 at example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [tst99655 at example.com] found. 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/cen.example.com/@tst99655 at example.com] to negative cache 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0040): No results for getpwnam call 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): User [tst99655 at example.com] does not exist in [cen.example.com]! (negative cache) 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0080): No matching domain found for [tst99655 at example.com], fail! 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:tst99655 at example.com:U at cen.example.com] 
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [client_recv] (0x0200): Client disconnected! 

This is log from client after: 
getent group csunix at cen.example.com 
id tst99655 at example.com 
uid=20018(tst99655 at cen.example.com) gid=5001(csunix) groups=5001(csunix) 

==> sssd_nss.log <== 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fe107283880:1:tst99655 at example.com@example.com] 

==> sssd_vs.example.com.log <== 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=tst99655 at example.com] 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): DP Request [Account #9]: New request. Flags [0x0001]. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=tst99655))][cn=Default Trust View,cn=views,cn=accounts,dc=vs,dc=example,dc=cz]. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_send] (0x0400): Executing extended operation 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [ipa_s2n_exop_done] (0x0040): ldap_extended_operation result: No such object(32), (null). 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [ipa_s2n_get_user_done] (0x0040): s2n exop request failed. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_req_done] (0x0400): DP Request [Account #9]: Request handler finished [0]: Success 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #9]: Receiving request data. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #9]: Finished. Success. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #9]: Returning [Success]: 0,0,Success 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1::example.com:name=tst99655 at example.com] from reply table 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #9]: Request removed. 
(Wed Jan 4 16:00:29 2017) [sssd[be[vs.example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 

==> sssd_nss.log <== 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [tst99655 at example.com] 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/example.com/tst99655 at example.com] to negative cache 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0040): No results for getpwnam call 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [tst99655 at example.com] 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values. 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning.. 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [tst99655 at example.com] 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fe107283880:1:tst99655 at example.com@example.com] 
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [client_recv] (0x0200): Client disconnected! 

looks like user's information are already in cache ... But why it can not be resolved without running getent group csunix first ? 
Sorry for long post. 

Jan 

---- 
> Hi, 
> 
> I have trouble with resolving AD users from my IPA clients. 
> 
> Environment: 2x IPA server with trust into AD - both IPA servers and clients running latest rhel 7.3. 
> 
> IPA domain: vs.example.com 
> AD domain: example.com, cen.example.com 
> 
> All tstxxxxx users are in cen.example.com but their UPN is set to tstxxxxx at example.com 
> 
> I can run id and getent passwd commands without problem from both IPA servers: 
> 
> id tst99655 at example.com 
> uid=20018(tst99655 at cen.example.com) gid=5001(csunix) groups=5001(csunix),930000008(final_test_group) 
> 
> getent tst99655 at example.com 
> tst99655 at cen.example.com:*:20018:5001:ipa_test:/home/cen.example.com/tst99655:/bin/bash 
> 
> But from client: 
> 
> root at trh7clnt02:~# id tst99655 at example.com 
> id: tst99655 at example.com: no such user 
> root at trh7clnt02:~#getent passwd tst99655 at example.com 
> ... no reply 
> 
> 
> But when I run on client: 
> getent group csunix at cen.example.com - it takes more then 30s 
> csunix at cen.example.com:*:5001: .... and really long list of users 
> 
> Then again from client: 
> 
> root at trh7clnt02:~# id tst99655 at example.com 
> uid=20018(tst99655 at cen.example.com) gid=5001(csunix) groups=5001(csunix) 
> 
> root at trh7clnt02:~# getent passwd tst99655 at example.com 
> tst99655 at cen.example.com:*:20018:5001:ipatest:/home/cen.example.com/tst99655:/bin/bash 
> 
> This time it works and it keeps working until I clean the sssd cache on client. Then I have to run that getent group csunix command again. 
> 
> I would say it is some timeout issue with enumerating csunix group. I have tried to fix it by adding: 
> 
> ldap_search_timeout = 50 

> I don't think this would be related to the searches timing out but 
> probably parsing and storing the entries on the server and the client. 

> Could you try adding this on the server side's sssd.conf? 

> [domain/domname] 
> subdomain_inherit = ignore_group_members 
> ignore_group_members = True 

> By the way, did you install 7.3 cleanly or did you upgrade? And if you 
> upgraded, did you ever removed the cache post-upgrade on the server? 

> There's been some improvements related to performance in 7.3 and even 
> more are coming in 7.4. 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170104/a4ad2d19/attachment.htm>