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

[Jan Karásek]

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 ***@example.com

I can run id and getent passwd commands without problem from both IPA servers:

id ***@example.com
uid=20018(***@cen.example.com) gid=5001(csunix) groups=5001(csunix),930000008(final_test_group)

getent ***@example.com
***@cen.example.com:*:20018:5001:ipa_test:/home/cen.example.com/tst99655:/bin/bash

But from client:

***@trh7clnt02:~# id ***@example.com
id: ***@example.com: no such user
***@trh7clnt02:~#getent passwd ***@example.com
... no reply


But when I run on client:
getent group ***@cen.example.com - it takes more then 30s
***@cen.example.com:*:5001: .... and really long list of users

Then again from client:

***@trh7clnt02:~# id ***@example.com
uid=20018(***@cen.example.com) gid=5001(csunix) groups=5001(csunix)

***@trh7clnt02:~# getent passwd ***@example.com
***@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

into sssd.conf on both server and client(sssd restarted), but without effect.
Here is my sssd.conf from client:

[domain/vs.example.com]
debug_level = 7
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = vs.example.com
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = trh7clnt02.vs.example.com
chpass_provider = ipa
ipa_server = tidmipa01.vs.example.com
ldap_tls_cacert = /etc/ipa/ca.crt
ldap_search_timeout = 50

[sssd]
services = nss, sudo, pam, ssh
config_file_version = 2
domains = vs.example.com
[nss]
homedir_substring = /home
debug_level = 7
[pam]
debug_level = 7
[sudo]
[autofs]
[ssh]
[pac]
debug_level = 7
[ifp]

IPA server sssd.conf:

[domain/vs.example.com]
debug_level = 7
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = vs.example.com
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = tidmipa01.vs.example.com
chpass_provider = ipa
ipa_server = tidmipa01.vs.example.com
ipa_server_mode = True
ldap_tls_cacert = /etc/ipa/ca.crt
ldap_id_mapping = False
ldap_search_timeout = 20
[sssd]
services = nss, sudo, pam, ssh
config_file_version = 2
domains = vs.example.com
[nss]
memcache_timeout = 600
debug_level = 7
homedir_substring = /home
[pam]
debug_level = 7
[sudo]
debug_level = 7
[autofs]
debug_level = 7
[ssh]
debug_level = 7
[pac]
debug_level = 7
[ifp]
debug_level = 7

Any suggestion how to fix that ? I can add logs from both successful and unsuccessful try but they are quite long.

Thank you.
Jan

[Jakub Hrozek]

Post by Jan Karásek
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
... no reply
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.
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.

[Jan Karásek]

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.

Post by Jakub Hrozek
By the way, did you install 7.3 cleanly or did you upgrade?

It has been upgraded.

Post by Jakub Hrozek
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 ***@example.com
uid=20018(***@cen.example.com) gid=5001(csunix) groups=5001(csunix)

Server:
uid=20018(***@cen.example.com) gid=5001(csunix) groups=5001(csunix),930000008(final_test_group)
***@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:***@[e-mail]]
(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=***@example.com:-]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:***@[e-mail]]

==> 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=***@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=***@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:***@example.com:***@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=***@example.com:U]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:***@example.com:***@vs.example.com]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:***@[e-mail]]

==> 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=***@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=***@example.com)(mail=***@example.com)(krbPrincipalName=tst99655\\@***@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 [***@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=***@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:***@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=***@example.com:U]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f864e2a6880:1:***@example.com:***@example.com]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:***@example.com:***@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=***@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=***@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 [***@example.com]
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [***@example.com] found.
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/cen.example.com/@***@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 [***@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 [***@example.com], fail!
(Wed Jan 4 15:21:22 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f864e2a6880:1:***@example.com:***@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 ***@cen.example.com
id ***@example.com
uid=20018(***@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:***@[e-mail]]

==> 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=***@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=***@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 [***@example.com]
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/example.com/***@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 [***@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 [***@example.com]
(Wed Jan 4 16:00:29 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fe107283880:1:***@[e-mail]]
(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


----

Post by Jakub Hrozek
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
... no reply
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.
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.

[Jakub Hrozek]

Post by Jan Karásek
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.

Post by Jakub Hrozek
By the way, did you install 7.3 cleanly or did you upgrade?

It has been upgraded.

Post by Jakub Hrozek
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'm sorry but I would need to see the whole logs to give a qualified
answer, really. Could you please remove or invalidate the caches on the
server and the client, then run:
date; id ***@example.com; date
and then attach or send directly to me the logs from both the server and
the client so I can match the logs with the date timestamps?

Feel free to obfuscate the domain, user and group names in the logs.