Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case: - get SSSD debug level set for a domain and nss section on IPA master used for resolution requests - issue your request - collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master used
for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
On 2/17/2019 7:43 PM, TomK via FreeIPA-users wrote:
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master
used for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
# id 994 uid=994(dirsrv) gid=990(dirsrv) groups=990(dirsrv)
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
On Sun, Feb 17, 2019 at 07:43:33PM -0500, TomK via FreeIPA-users wrote:
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master used
for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
You can ignore this. SSSD's authdata plugin called from inside 389ds tries to send the PAC of the current DS user to SSSD's PAC responder to process the group membership.
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
so, please check the DNS setup on this server.
HTH
bye, Sumit
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On 2/18/2019 4:25 AM, Sumit Bose via FreeIPA-users wrote:
On Sun, Feb 17, 2019 at 07:43:33PM -0500, TomK via FreeIPA-users wrote:
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master used for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
You can ignore this. SSSD's authdata plugin called from inside 389ds tries to send the PAC of the current DS user to SSSD's PAC responder to process the group membership.
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^so, please check the DNS setup on this server.
HTH
bye, Sumit
I guess this is it:
https://docs.pagure.org/SSSD.sssd/users/relnotes/notes_1_16_1.html https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/7/htm...
auto_private_groups (string) If this option is enabled, SSSD will automatically create user private groups based on user's UID number. The GID number is ignored in this case.
For POSIX subdomains, setting the option in the main domain is inherited in the subdomain.
For ID-mapping subdomains, auto_private_groups is already enabled for the subdomains and setting it to false will not have any effect for the subdomain.
NOTE: Because the GID number and the user private group are inferred from the UID number, it is not supported to have multiple entries with the same UID or GID number with this option. In other words, enabling this option enforces uniqueness across the ID space.
Default: False
[ IPA03 ]
ipa-server-4.6.4-10.el7.centos.2.x86_64 sssd-1.16.2-13.el7_6.5.x86_64 CentOS Linux release 7.6.1810 (Core)
[ IPA01 ]
sssd-1.15.2-50.el7_4.8.x86_64 ipa-server-4.5.0-22.el7.centos.x86_64 CentOS Linux release 7.3.1611 (Core)
I simply used the primary defined group that was assigned in the AD DC instead of the above, given that this feature is now turned off by default.
Cheers, TK
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On Mon, Feb 18, 2019 at 04:10:34PM -0500, TomK via FreeIPA-users wrote:
On 2/18/2019 4:25 AM, Sumit Bose via FreeIPA-users wrote:
On Sun, Feb 17, 2019 at 07:43:33PM -0500, TomK via FreeIPA-users wrote:
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master used for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
You can ignore this. SSSD's authdata plugin called from inside 389ds tries to send the PAC of the current DS user to SSSD's PAC responder to process the group membership.
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^so, please check the DNS setup on this server.
HTH
bye, Sumit
I guess this is it:
https://docs.pagure.org/SSSD.sssd/users/relnotes/notes_1_16_1.html https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/7/htm...
auto_private_groups (string) If this option is enabled, SSSD will automatically create user private groups based on user's UID number. The GID number is ignored in this case.
For POSIX subdomains, setting the option in the main domain is inherited in the subdomain.
For ID-mapping subdomains, auto_private_groups is already enabled for the subdomains and setting it to false will not have any effect for the subdomain.
NOTE: Because the GID number and the user private group are inferred from the UID number, it is not supported to have multiple entries with the same UID or GID number with this option. In other words, enabling this option enforces uniqueness across the ID space.
Default: False
Although there might be some unwanted side effect of this change I doubt that it is related here.
Do you have an idea why DNS servers were not reachable?
bye, Sumit
[ IPA03 ]
ipa-server-4.6.4-10.el7.centos.2.x86_64 sssd-1.16.2-13.el7_6.5.x86_64 CentOS Linux release 7.6.1810 (Core)
[ IPA01 ]
sssd-1.15.2-50.el7_4.8.x86_64 ipa-server-4.5.0-22.el7.centos.x86_64 CentOS Linux release 7.3.1611 (Core)
I simply used the primary defined group that was assigned in the AD DC instead of the above, given that this feature is now turned off by default.
Cheers, TK
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On 2/19/2019 2:44 AM, Sumit Bose via FreeIPA-users wrote:
On Mon, Feb 18, 2019 at 04:10:34PM -0500, TomK via FreeIPA-users wrote:
On 2/18/2019 4:25 AM, Sumit Bose via FreeIPA-users wrote:
On Sun, Feb 17, 2019 at 07:43:33PM -0500, TomK via FreeIPA-users wrote:
On 2/17/2019 2:19 PM, Alexander Bokovoy via FreeIPA-users wrote:
On Sun, 17 Feb 2019, TomK via FreeIPA-users wrote:
Hey All,
Scenario:
Two IPA clusters, both with a unique trust to the same AD DC. One picks up the private group, the other doesn't. I can login with the AD user to both:
IPA Cluster 1 (ipa01, ipa02) - a.abc.123 # getent group alex@abc.123 alex@abc.123:*:155601104: #
IPA Cluster 2 (ipa03, ipa04) - b.abc.123 # getent group alex@abc.123 #
Curious if anyone ran into the above before and is willing to throw in a hint or two? Would be appreciated.
You need to start with standard debugging technique for this case:
- get SSSD debug level set for a domain and nss section on IPA master used for resolution requests
- issue your request
- collect sssd logs and see what happens
If you have it working on IPA master but not on IPA client, gather the same amount of logs on both IPA client and IPA master from the same time frame.
SSSD troubleshooting page is https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
Thanks Alex. Aware but just have the snippet for now. Was going to take a few quick tips and then dig through the logs myself later.
Nontheless, suspect it's selinux being enabled when it was being installed. I may blow away the cluster and rebuild if fixing things will take longer.
(Sun Feb 17 18:46:19 2019) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[994] egid[990] pid[15730]. (Sun Feb 17 18:46:19 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [994].
You can ignore this. SSSD's authdata plugin called from inside 389ds tries to send the PAC of the current DS user to SSSD's PAC responder to process the group membership.
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[16473]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e2be292510][21] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #97: Setting "Group by name" plugin (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #97: New request 'Group by name' (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #97: Parsing input name [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'alex@abc.123' matched expression for domain 'abc.123', user is alex (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #97: Setting name [alex] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #97: Performing a single domain search (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #97: Search will check the cache and check the data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain abc.123 type POSIX is valid (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #97: Using domain [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #97: Preparing input data for domain [abc.123] rules (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #97: Looking up alex@abc.123 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: Checking negative cache for [alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/abc.123/alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #97: [alex@abc.123] is not present in negative cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be295ce0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be295ce0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #97: Looking up [alex@abc.123] in data provider (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [abc.123][0x2][BE_REQ_GROUP][name=alex@abc.123:-] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55e2bd6f6f00:2:alex@abc.123@abc.123]
==> sssd_b.abc.123.log <== (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): dbus conn: 0x5614c6e05360 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=alex@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_print_server] (0x2000): Searching 192.168.0.154:389 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaGroupOverride)(cn=alex))][cn=Default Trust View,cn=views,cn=accounts,dc=mws,dc=mds,dc=xyz]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[0x5614c6e33690], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaGroupOverride)(cn=alex))]. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0100): Resetting the status of port 0 for server '(no name)' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_srv_data_status] (0x0400): Changing state of SRV lookup from 'SRV_RESOLVE_ERROR' to 'SRV_NEUTRAL'. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain abc.123 and site Default-First-Site-Name (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: sh[0x5614c6e24c00], connected[1], ops[(nil)], ldap[0x5614c6e113f0] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [request_watch_destructor] (0x0400): Deleting request watch (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolv_discover_srv_done] (0x0040): SRV query failed [11]: Could not contact DNS servers
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^so, please check the DNS setup on this server.
HTH
bye, Sumit
I guess this is it:
https://docs.pagure.org/SSSD.sssd/users/relnotes/notes_1_16_1.html https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/7/htm...
auto_private_groups (string) If this option is enabled, SSSD will automatically create user private groups based on user's UID number. The GID number is ignored in this case.
For POSIX subdomains, setting the option in the main domain is inherited in the subdomain.
For ID-mapping subdomains, auto_private_groups is already enabled for the subdomains and setting it to false will not have any effect for the subdomain.
NOTE: Because the GID number and the user private group are inferred from the UID number, it is not supported to have multiple entries with the same UID or GID number with this option. In other words, enabling this option enforces uniqueness across the ID space.
Default: False
Although there might be some unwanted side effect of this change I doubt that it is related here.
Do you have an idea why DNS servers were not reachable?
The FreeIPA installation here was net new, done using:
yum install -y "*ipa-server" "*ipa-server-trust-ad" bind bind-dyndb-ldap ipa-server-dns ipa-adtrust-install ipa-server-dns
ipa-server-install --setup-dns --forwarder=192.168.0.123 -p "ForgotMyPassword" -a "ForgotMyPassword" -r b.abc.123 -n b.abc.123 --hostname ipa03.b.abc.123
This configured forwarders under the DNS Servers tab. In addition I've setup forwarders manually under the DNS Forward Zones section manually, initially not seeing the above defined anywhere after the install.
Zone name Status Zone forwarders Forward policy abc.123. Enabled 192.168.0.123, 192.168.0.124, 192.168.0.125 only
Even with a resolv.conf as follows:
# cat /etc/resolv.conf search b.abc.123 abc.123 nameserver 127.0.0.1
abc.123 being the AD / Windows Domain.
To get it to resolve again, I've removed the forwarders in the DNS Servers section leaving only the one defined in the DNS Forward Zone section, set selinux policy to PERMISSIVE and restarted. Once that was done resolution worked but the group lookup still failed.
However all related DNS errors I posted below disappeared, yet the group lookup still failed to work.
So that led me to believe on a few searches that that new private group option could be the issue. I haven't tried to use it yet however since I felt no need too. I simply used the default primary group, but I still can try in this env.
At this point I've reset selinux policy to enforcing, rebooted, and everything still works with the DNS.
I did save the logs of each attempt at debug_level=10 and can send over if that helps.
Cheers, TK
bye, Sumit
[ IPA03 ]
ipa-server-4.6.4-10.el7.centos.2.x86_64 sssd-1.16.2-13.el7_6.5.x86_64 CentOS Linux release 7.6.1810 (Core)
[ IPA01 ]
sssd-1.15.2-50.el7_4.8.x86_64 ipa-server-4.5.0-22.el7.centos.x86_64 CentOS Linux release 7.3.1611 (Core)
I simply used the primary defined group that was assigned in the AD DC instead of the above, given that this feature is now turned off by default.
Cheers, TK
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_set_port_status] (0x0100): Marking port 0 of server '(no name)' as 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [resolve_srv_done] (0x0040): Unable to resolve SRV [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_gc_abc.123' as 'not resolved' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x0080): Couldn't resolve server (SRV lookup meta-server), resolver returned [1432158237]: SRV lookup error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_process] (0x1000): Trying with the next one! (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Subdomain lookup failed, will try to reset subdomain. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of subdom abc.123 from forest abc.123 is: two-way trust (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_retried] (0x0400): Subdomain re-set, will retry lookup (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x1000): Resetting all servers in service abc.123 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [abc.123] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain b.abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'not working' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [fo_resolve_service_send] (0x0020): No available servers for service 'sd_gc_abc.123' (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_connect_done] (0x4000): notify error to op #1: 5 [Input/output error] (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_dom_offline] (0x1000): Marking subdomain abc.123 offline (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5614c6dd6ab0
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5614c6dda000
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Running timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Destroying timer event 0x5614c6dda000 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ldb] (0x4000): Ending timer event 0x5614c6dd6ab0 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [be_mark_subdom_offline] (0x1000): Marking subdomain abc.123 as inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158272]: Subdomain is inactive. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_reply_std] (0x1000): DP Request [Account #110]: Returning [Internal Error]: 3,1432158272,Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:2::abc.123:name=alex@abc.123] from reply table (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sun Feb 17 18:46:19 2019) [sssd[be[b.abc.123]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x55e2be287340 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x55e2be2883d0 (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 3 errno: 1432158272 error message: Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #97: Data Provider Error: 3, 1432158272, Subdomain is inactive (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #97: Due to an error we will return cached data (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Looking up [alex@abc.123] in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55e2be29b240
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55e2be29a6d0
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x55e2be29a6d0 "ltdb_timeout"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x55e2be29b240 "ltdb_callback"
(Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #97: Object [alex@abc.123] was not found in cache (Sun Feb 17 18:46:19 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #97: Finished: Not found
==> sssd_b.abc.123.log <==
==> sssd_nss.log <== (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain abc.123 is Active (Sun Feb 17 18:46:19 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found (Sun Feb 17 18:46:19 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55e2bd6f6f00:2:alex@abc.123@abc.123] (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected! (Sun Feb 17 18:46:19 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x55e2be292510][21]
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
-- Cheers, Tom K.
Living on earth is expensive, but it includes a free trip around the sun. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
freeipa-users@lists.fedorahosted.org
-
Alexander Bokovoy -
Sumit Bose -
TomK