[Freeipa-users] replica running trust-agents can't resolve AD users - which of these sssd errors should I be focusing on?

Fri Dec 23 09:40:19 UTC 2016

On Thu, Dec 22, 2016 at 11:34:01PM +0200, Alexander Bokovoy wrote:
> On to, 22 joulu 2016, Chris Dagdigian wrote:
> > Hi folks,
> > 
> > Summary:  Replica w/ Trust agents can't resolve AD users. Not sure which
> > debug_level=log error I should focus on. Would appreciate extra eyeballs
> > on this ..
> > 
> > Have a brand new replica (v4.4) running and after installing the AD
> > trust agents I still can't recognize users who exist in the trusted AD
> > domains.
> > 
> > Running at debug_level=10 for logging as usual however deleting the logs
> > and doing a fresh reboot followed by trying to resolve a users still
> > make 4000+ log entries so rather than include it here I've posted a
> > sanitized sssd_domain.log file here:
> > 
> > http://chrisdag.me/sssd_companyidm.org.log.txt
> > 
> > There are two sets of messages in that massive log file that concern me
> > but I don't know enough yet to figure out which one to focus on.
> > 
> > The first set of messages show what appears to be a fatal error in
> > connecting to the local ldap:// server on the replica.
> > 
> > However -
> > - dirsirv logs look fine
> > - the various ldapsearch commands in the Free-IPA troublehooting page
> > work to query both the replica and the remote master
> > - 'ipactl status' shows directory services running
> > - no firewall blocking and AWS VPC flowLogs show no REJECT traffic
> > whatsoever for the NIC on the replica
> Can you show us ldap_child.log and krb5_child.log from /var/log/sssd on
> the replica?
> 
> There seem to be something weird with networking stack, because at
> 15:43:13 the next attempt to connect gets 'connection refused'. May be
> 389-ds is just warming up and there is not enough CPU or I/O to handle
> the load?
> 
> (Thu Dec 22 15:43:13 2016) [sssd[be[companyidm.org]]]
> [be_resolve_server_process] (0x0200): Found address for server usaeilidmp002.companyidm.org: [10.127.66.11] TTL 7200
> (Thu Dec 22 15:43:13 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x4000): Using file descriptor [27] for the connection.
> (Thu Dec 22 15:43:13 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
> (Thu Dec 22 15:43:13 2016) [sssd[be[companyidm.org]]]
> [sssd_async_connect_done] (0x0020): connect failed [111][Connection refused].
> (Thu Dec 22 15:43:13 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [111]: Connection refused.
> 
> this is definitely is different from the result of two seconds before:
> 
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x4000): Using file descriptor [21] for the connection.
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sssd_async_connect_send] (0x0020): connect failed [101][Network is unreachable].
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [101]: Network is unreachable.
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_state_destructor] (0x0400): closing socket [21] (Thu Dec
> 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [101]: Network is unreachable.
> (Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
> [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [101]: Network is unreachable.
> 
> Later, in a minute it seems to respond just well:
> 
> 
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x4000): Using file descriptor [27] for the connection.
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://usaeilidmp002.companyidm.org:389/??base] with fd [27].
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_get_rootdse_send] (0x4000): Getting rootdse
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_print_server] (0x2000): Searching 10.127.66.11:389
> ...
> 
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]] [sdap_parse_range]
> (0x2000): No sub-attributes for [supportedSASLMechanisms]
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]] [sdap_parse_range]
> (0x2000): No sub-attributes for [defaultNamingContext]
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]] [sdap_parse_range]
> (0x2000): No sub-attributes for [lastUSN]
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_process_result] (0x2000): Trace: sh[0x7f4f63ace530], connected[1], ops[0x7f4f63b283d0], ldap[0x7f4f63b28720]
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_op_destructor] (0x2000): Operation 1 finished
> (Thu Dec 22 15:44:28 2016) [sssd[be[companyidm.org]]]
> [sdap_get_rootdse_done] (0x2000): Got rootdse
> 
> So, sssd on the replica is able to retrieve information from the
> replica's LDAP server. It also is able to retrieve the trust topology
> information and retrieve the trusted domain objects to use against the
> forest root domains your deployment trusts.
> 
> But at the point when it tries to contact global catalog and domain
> controllers from the trusted domains, it cannot access them, so it
> considers them offline.
> 
> Can you show us your /etc/krb5.conf on this replica, content of files in
> /var/lib/sss/pubconf/krb5.include.d subdirectory which get included into
> /etc/krb5.conf, and the logs I asked above?
> 
> Can you make sure that the replica is actually able to reach AD DCs for
> the trusted domains (ports tcp/3268, tcp/389, tcp/88, udp/88, udp/53 at
> least)?

In addition, can you also see if the keytab with the trust principal is
there? Probably it would be /var/lib/sss/keytabs/shanetest.org.

At 15:43:11, sssd tried to fetch the keytab for this trust:
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [ipa_server_trusted_dom_setup_1way] (0x0400): Will re-fetch keytab for shanetest.org
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [ipa_getkeytab_send] (0x0400): Retrieving keytab for companyidm$@SHANETEST.ORG from usaeilidmp002.companyidm.org into /var/lib/sss/keytabs/shanetest.org.keytabRw7Iai using ccache /var/lib/sss/db/ccache_companyidm.ORG

But fails:
SASL Bind failed Can't contact LDAP server (-1) !
Failed to bind to server!
Failed to get keytab
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [ipa_getkeytab_done] (0x0040): ipa-getkeytab failed with status [2304]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [ipa_getkeytab_recv] (0x2000): ipa-getkeytab status 2304
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [ipa_server_trust_1way_kt_done] (0x0080): ipa_getkeytab_recv failed: 1432158265

What I don't see in the logs, though is that if we try and re-fetch the
keytab after going online (we should, though).

> 
> > The second scary thing I see relates to some "Invalid Argument" errors
> > related to ipa_get_*_acct stuff that I see when I try to resolve my AD
> > user account:
> These are coming from the failure to contact trusted domain's GC or LDAP
> servers. Looking at the code flow, it seems an attempt to actually
> connect to the server failed and there was no retry allowed
> (internally), so SSSD marked the subdomain it tried to connect to as
> 'offline'.
> 
> So I'd bet you have something blocking access from the replica towards
> domain controllers of those AD domains.
> 
> -- 
> / Alexander Bokovoy
> 
> -- 
> Manage your subscription for the Freeipa-users mailing list:
> https://www.redhat.com/mailman/listinfo/freeipa-users
> Go to http://freeipa.org for more info on the project