Please help me find what broke down with my AD authentications

[Mike Conner]

I have a one-way trust configured to AD. It has been working for a long time but has
stopped and I can't track down what has happened.
`getent passwd user` works on users in IPA, but fails (nothing returned) on AD users.

**** Contents of sssd.conf on client:
[domain/ipa.domain.edu]

cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = ipa.domain.edu
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = test.ipa.domain.edu
chpass_provider = ipa
ipa_server = _srv_,ipa.ipa.grinnell.edu
ipa_server_mode = true
ldap_tls_cacert = /etc/ipa/ca.crt
krb5_validate = False
debug_level=8

[sssd]
services = nss, sudo, pam, ssh
domains = ipa.domain.edu

[nss]
homedir_substring = /home
****
`ipa trustdomain-find` returns the trusted AD domain

I haven't found anything I can make sense of in the logs, but this might be a clue to
someone else:
**** From the sssd_ipa.domain.edu.log
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain ipa.domain.edu is Active
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain domain.edu is Active
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [ipa_srv_ad_acct_lookup_step]
(0x0400): Looking up AD account
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain ipa.domain.edu is Active
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain domain.edu is Active
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [be_mark_dom_offline] (0x1000):
Marking subdomain domain.edu offline
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [be_mark_subdom_offline] (0x1000):
Marking subdomain domain.edu as inactive
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [ipa_srv_ad_acct_lookup_done]
(0x0040): ipa_get_*_acct request failed: [22]: Invalid argument.
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [ipa_subdomain_account_done]
(0x0040): ipa_get_*_acct request failed: [22]: Invalid argument.
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [dp_req_done] (0x0400): DP Request
[Account #20]: Request handler finished [0]: Success
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [_dp_req_recv] (0x0400): DP Request
[Account #20]: Receiving request data.
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_list_success]
(0x0400): DP Request [Account #20]: Finished. Success.
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_std] (0x1000): DP
Request [Account #20]: Returning [Internal Error]: 3,22,Invalid argument
(Thu Feb 11 12:07:19 2021) [sssd[be[ipa.domain.edu]]] [dp_table_value_destructor]
(0x0400): Removing [0:1:0x0001:1::domain.edu:name=[e-mail]] from reply table
****

[Mike Conner]

This additional bit from the logs indicates a failure to retireve a keytab:
****
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [main] (0x0400): Backend provider
(ipa.domain.edu) started!
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain domain.edu is Active
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_send]
(0x1000): Trust direction of subdom domain.edu from forest domain.edu is: one-way inbound:
local domain trusts the remote domain
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_1way]
(0x0400): Will re-fetch keytab for domain.edu
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_getkeytab_send] (0x0400):
Retrieving keytab for IPA$(a)DOMAIN.EDU from test.ipa.domain.edu into
/var/lib/sss/keytabs/domain.edu.keytabDHvyo4 using ccache
/var/lib/sss/db/ccache_ipa.domain.edu
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
Setting up signal handler up for pid [80814]
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
Signal handler set up for pid [80814]
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x556b59a5db00
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x556b59a5db00
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d700 (14), R/- (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d6b0 (14), -/W (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d700 (14), R/- (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d6b0 (14), -/W (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d700 (14), R/- (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d6b0 (14), -/W (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d700 (14), R/- (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a20780/0x556b59a5d6b0 (14), -/W (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_remove_timeout] (0x2000):
0x556b59a5e9c0
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x556b59a5db00
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000):
Dispatching.
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [id_callback] (0x0100): Got id ack
and version (1) from Monitor
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
(0x0200): Entering.
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
(0x0200): Adding connection 0x556b59a85950.
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_init_connection] (0x0400):
Adding connection 0x556b59a85950
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_add_watch] (0x2000):
0x556b59a8f920/0x556b59a80e30 (18), -/W (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a8f920/0x556b59a7e380 (18), R/- (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
(0x0200): Got a connection
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [dp_client_init] (0x0100): Set-up
Backend ID timeout [0x556b59a8ec30]
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.sssd.DataProvider.Client with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_conn_register_path] (0x0400):
Registering object path /org/freedesktop/sssd/dataprovider with D-Bus connection
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.DBus.Properties with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.DBus.Introspectable with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.sssd.dataprovider with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.sssd.DataProvider.Backend with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.sssd.DataProvider.Failover with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
(0x0400): Registering interface org.freedesktop.sssd.DataProvider.AccessControl with path
/org/freedesktop/sssd/dataprovider
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x556b59a85950
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a8f920/0x556b59a7e380 (18), R/- (disabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a8f920/0x556b59a80e30 (18), -/W (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a8f920/0x556b59a7e380 (18), R/- (enabled)
(Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x556b59a8f920/0x556b59a80e30 (18), -/W (disabled)
Unable to initialize STARTTLS session
Failed to bind to server!
Failed to get keytab
***

[Sumit Bose]

On Thu, Feb 11, 2021 at 10:20:45PM -0000, Mike Conner via FreeIPA-users wrote:
>  This additional bit from the logs indicates a failure to retireve a
> keytab:
>  ****
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [main] (0x0400): Backend provider
> (ipa.domain.edu) started!
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
> Domain domain.edu is Active
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_send]
> (0x1000): Trust direction of subdom domain.edu from forest domain.edu is: one-way inbound:
> local domain trusts the remote domain
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_1way]
> (0x0400): Will re-fetch keytab for domain.edu
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [ipa_getkeytab_send] (0x0400):
> Retrieving keytab for IPA$(a)DOMAIN.EDU from test.ipa.domain.edu into
> /var/lib/sss/keytabs/domain.edu.keytabDHvyo4 using ccache
> /var/lib/sss/db/ccache_ipa.domain.edu
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
> Setting up signal handler up for pid [80814]
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
> Signal handler set up for pid [80814]
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x556b59a5db00
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x556b59a5db00
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d700 (14), R/- (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d6b0 (14), -/W (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d700 (14), R/- (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d6b0 (14), -/W (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d700 (14), R/- (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d6b0 (14), -/W (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d700 (14), R/- (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a20780/0x556b59a5d6b0 (14), -/W (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_remove_timeout] (0x2000):
> 0x556b59a5e9c0
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x556b59a5db00
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000):
> Dispatching.
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [id_callback] (0x0100): Got id ack
> and version (1) from Monitor
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
> (0x0200): Entering.
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
> (0x0200): Adding connection 0x556b59a85950.
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_init_connection] (0x0400):
> Adding connection 0x556b59a85950
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_add_watch] (0x2000):
> 0x556b59a8f920/0x556b59a80e30 (18), -/W (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a8f920/0x556b59a7e380 (18), R/- (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_server_init_new_connection]
> (0x0200): Got a connection
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [dp_client_init] (0x0100): Set-up
> Backend ID timeout [0x556b59a8ec30]
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.sssd.DataProvider.Client with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_conn_register_path] (0x0400):
> Registering object path /org/freedesktop/sssd/dataprovider with D-Bus connection
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.DBus.Properties with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.DBus.Introspectable with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.sssd.dataprovider with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.sssd.DataProvider.Backend with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.sssd.DataProvider.Failover with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_opath_hash_add_iface]
> (0x0400): Registering interface org.freedesktop.sssd.DataProvider.AccessControl with path
> /org/freedesktop/sssd/dataprovider
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x556b59a85950
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a8f920/0x556b59a7e380 (18), R/- (disabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a8f920/0x556b59a80e30 (18), -/W (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a8f920/0x556b59a7e380 (18), R/- (enabled)
>  (Thu Feb 11 15:45:13 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x556b59a8f920/0x556b59a80e30 (18), -/W (disabled)
>  Unable to initialize STARTTLS session 
Hi,

SSSD is calling ipa-getkeytab here, does it work if you call
ipa-getkeytab manually? Please make sure you use the '--retrieve' option
to not override existing keys.

The STARTTLS might indicate issues with certificates. Have you check if
maybe a related certificate is expired?

bye,
Sumit

>  Failed to bind to server!
>  Failed to get keytab
>  ***
>  _______________________________________________
>  FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
>  To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
>  Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
>  List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
>  List Archives:
> https://lists.fedorahosted.org/archives/list/[e-mail]...
>  Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Mike Conner]

I'm afraid I don't know how to construct the right ipa-getkeytab command to test.
Do I run ipa-getkeytab on the client or on the ipa server? For the IPA$(a)DOMAIN.EDU
principal?

I thought about STARTTLS pointing to a certificate issue. The certs on the ipa server are
not expired:

getcert list | grep expires
	expires: 2022-06-18 21:28:39 UTC
	expires: 2022-05-24 03:14:46 UTC
	expires: 2022-05-24 03:15:16 UTC
	expires: 2022-05-24 03:14:56 UTC
	expires: 2038-07-11 18:11:01 UTC
	expires: 2022-05-24 03:14:38 UTC
	expires: 2022-08-01 03:40:17 UTC
	expires: 2022-06-15 03:14:35 UTC
	expires: 2022-06-15 03:14:50 UTC

Could it be an issue with an expired certificate on the AD end?
Thank you!

[Mike Conner]

The certificate for the AD secure ldap server is also current (ad.domain.edu:636).

[Rob Crittenden]

Mike Conner via FreeIPA-users wrote:
>  The certificate for the AD secure ldap server is also current
> (ad.domain.edu:636). 
It would only be binding to IPA for ipa-getkeytab. I don't know how sssd
invokes it.

But you should be able to see a failed TLS connection in the 389-ds logs
which could help point the way.

rob

[Mike Conner]

The following is a portion of the sssd log on the client reflecting the same inability to
retrieve keytab:
***
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain domain.edu is Active
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_send]
(0x1000): Trust direction of subdom domain.edu from forest domain.edu is: one-way inbound:
local domain trusts the remote domain
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_1way]
(0x0400): Will re-fetch keytab for domain.edu
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_getkeytab_send] (0x0400):
Retrieving keytab for IPA$(a)domain.EDU from test.ipa.domain.edu into
/var/lib/sss/keytabs/domain.edu.keytabENwf67 using ccache
/var/lib/sss/db/ccache_IPA.DOMAIN.EDU
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
Setting up signal handler up for pid [88300]
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
Signal handler set up for pid [88300]
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x5578611b8b00
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x5578611b8b00
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x55786117b780/0x5578611b8700 (14), R/- (disabled)
(Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
0x55786117b780/0x5578611b86b0 (14), -/W (enabled)
***

At the same time, the errors log on the IPA server
(/var/log/dirsrv/slapd_IPA-DOMAIN-EDU/errors) does not log any errors (TLS or otherwise):
***
[12/Feb/2021:10:08:10.990268019 -0600] - INFO - slapd_daemon - slapd started.  Listening
on All Interfaces port 389 for LDAP requests
[12/Feb/2021:10:08:10.992126928 -0600] - INFO - slapd_daemon - Listening on All Interfaces
port 636 for LDAPS requests
[12/Feb/2021:10:08:10.993036367 -0600] - INFO - slapd_daemon - Listening on
/var/run/slapd-IPA-DOMAIN-EDU.socket for LDAPI requests
[12/Feb/2021:10:08:11.058722880 -0600] - ERR - schema-compat-plugin - schema-compat-plugin
tree scan will start in about 5 seconds!
[12/Feb/2021:10:08:16.148838179 -0600] - ERR - schema-compat-plugin - warning: no entries
set up under cn=computers, cn=compat,dc=ipa,dc=domain,dc=edu
[12/Feb/2021:10:08:16.150531968 -0600] - ERR - schema-compat-plugin - Finished plugin
initialization.
***

Thanks!

[Mike Conner]

This may be useful information: Clients are still able to lookup and authenticate AD users
as long as they have an in-tact cache. If I empty the sssd cache, that client will no
longer be able to perform AD lookups or authentications.

[Rob Crittenden]

Mike Conner via FreeIPA-users wrote:
>  The following is a portion of the sssd log on the client reflecting
> the same inability to retrieve keytab:
>  ***
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
> Domain domain.edu is Active
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_send]
> (0x1000): Trust direction of subdom domain.edu from forest domain.edu is: one-way inbound:
> local domain trusts the remote domain
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_server_trusted_dom_setup_1way]
> (0x0400): Will re-fetch keytab for domain.edu
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [ipa_getkeytab_send] (0x0400):
> Retrieving keytab for IPA$(a)domain.EDU from test.ipa.domain.edu into
> /var/lib/sss/keytabs/domain.edu.keytabENwf67 using ccache
> /var/lib/sss/db/ccache_IPA.DOMAIN.EDU
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
> Setting up signal handler up for pid [88300]
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [child_handler_setup] (0x2000):
> Signal handler set up for pid [88300]
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x5578611b8b00
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x5578611b8b00
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x55786117b780/0x5578611b8700 (14), R/- (disabled)
>  (Fri Feb 12 10:11:54 2021) [sssd[be[ipa.domain.edu]]] [sbus_toggle_watch] (0x4000):
> 0x55786117b780/0x5578611b86b0 (14), -/W (enabled)
>  ***
>  
>  At the same time, the errors log on the IPA server
> (/var/log/dirsrv/slapd_IPA-DOMAIN-EDU/errors) does not log any errors (TLS or otherwise):
>  ***
>  [12/Feb/2021:10:08:10.990268019 -0600] - INFO - slapd_daemon - slapd started.  Listening
> on All Interfaces port 389 for LDAP requests
>  [12/Feb/2021:10:08:10.992126928 -0600] - INFO - slapd_daemon - Listening on All
> Interfaces port 636 for LDAPS requests
>  [12/Feb/2021:10:08:10.993036367 -0600] - INFO - slapd_daemon - Listening on
> /var/run/slapd-IPA-DOMAIN-EDU.socket for LDAPI requests
>  [12/Feb/2021:10:08:11.058722880 -0600] - ERR - schema-compat-plugin -
> schema-compat-plugin tree scan will start in about 5 seconds!
>  [12/Feb/2021:10:08:16.148838179 -0600] - ERR - schema-compat-plugin - warning: no entries
> set up under cn=computers, cn=compat,dc=ipa,dc=domain,dc=edu
>  [12/Feb/2021:10:08:16.150531968 -0600] - ERR - schema-compat-plugin - Finished plugin
> initialization.
>  *** 
LDAP connections are not logged in errors. You need to look in access.

rob

[Sumit Bose]

On Fri, Feb 12, 2021 at 02:10:09PM -0000, Mike Conner via FreeIPA-users wrote:
>  I'm afraid I don't know how to construct the right
> ipa-getkeytab command to test. Do I run ipa-getkeytab on the client or on the ipa server?
> For the IPA$(a)DOMAIN.EDU principal? 
Hi,

SSSD calls

    KRB5CCNAME=/var/lib/sss/db/ccache_ipa.domain.edu /usr/sbin/ipa-getkeytab -r -s
test.ipa.domain.edu -p 'IPA$(a)DOMAIN.EDU' -k
/var/lib/sss/keytabs/domain.edu.keytab-test

I added '-test' to the keytab name to not overwrite the ones created by
SSSD. The Kerberos credentail cache
/var/lib/sss/db/ccache_ipa.domain.edu has the Kerberos TGT of the host
account which should have the proper permissions to request a keytab.

HTH

bye,
Sumit

>  
>  I thought about STARTTLS pointing to a certificate issue. The certs on the ipa server are
> not expired:
>  
>  getcert list | grep expires
>  	expires: 2022-06-18 21:28:39 UTC
>  	expires: 2022-05-24 03:14:46 UTC
>  	expires: 2022-05-24 03:15:16 UTC
>  	expires: 2022-05-24 03:14:56 UTC
>  	expires: 2038-07-11 18:11:01 UTC
>  	expires: 2022-05-24 03:14:38 UTC
>  	expires: 2022-08-01 03:40:17 UTC
>  	expires: 2022-06-15 03:14:35 UTC
>  	expires: 2022-06-15 03:14:50 UTC
>  
>  Could it be an issue with an expired certificate on the AD end?
>  Thank you!
>  _______________________________________________
>  FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
>  To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
>  Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
>  List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
>  List Archives:
> https://lists.fedorahosted.org/archives/list/[e-mail]...
>  Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Mike Conner]

Thank you. I've run the following command on the broken client. In this instance
'ipa.ipa.domain.edu' is the IPA server. 'IPA$(a)DOMAIN.EDU' was used simply
because it's what I saw in the logs.

KRB5CCNAME=/var/lib/sss/db/ccache_IPA.DOMAIN.EDU /usr/sbin/ipa-getkeytab -r -s
ipa.ipa.domain.edu -p 'IPA$(a)DOMAIN.EDU' -k
/var/lib/sss/keytabs/domain.edu.keytab-test

The result is:
`Failed to load translations
Failed to parse result: Insufficient access rights

Failed to get keytab`

[Alexander Bokovoy]

On pe, 12 helmi 2021, Mike Conner via FreeIPA-users wrote:
> Thank you. I've run the following command on the broken client. In
> this
> instance 'ipa.ipa.domain.edu' is the IPA server. 'IPA$(a)DOMAIN.EDU' was
> used simply because it's what I saw in the logs.
>
> KRB5CCNAME=/var/lib/sss/db/ccache_IPA.DOMAIN.EDU /usr/sbin/ipa-getkeytab -r -s
> ipa.ipa.domain.edu -p 'IPA$(a)DOMAIN.EDU' -k
> /var/lib/sss/keytabs/domain.edu.keytab-test
>
> The result is:
> `Failed to load translations
> Failed to parse result: Insufficient access rights
>
> Failed to get keytab` 
This is expected behavior because you are running the command on a wrong
host. 'IPA$DOMAIN.EDU' is a trusted domain object that is highly
privileged as it represents whole IPA domain in view of a trusted Active
Directory forest. Only IPA replicas with 'trust agent' or 'trust
controller' roles have access to it. There is explicit ACIs set to allow
such access only to host/... principals of those IPA replicas.

The command Sumit asked you to run should be ran on IPA master, not the
client. E.g., on ipa.ipa.domain.edu.

-- 
/ Alexander Bokovoy
Sr. Principal Software Engineer
Security / Identity Management Engineering
Red Hat Limited, Finland

[Mike Conner]

Thank you for the clarification. I ran in on the IPA server and the keytab was
successfully retrieved.

`Keytab successfully retrieved and stored in:
/var/lib/sss/keytabs/domain.edu.keytab-test`

-Mike

[Mike Conner]

More logs. This is from another broken client during an attempt to login as an AD user:
****
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
Domain domain.edu is Active
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_get_acct_info_send]
(0x0400): Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user
[S-1-5-21-71189414-1642862984-1097818727-22197] to IPA server
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 16
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_op_add] (0x2000): New
operation 16 timeout 6
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
Trace: sh[0x55eb482586a0], connected[1], ops[0x55eb482c6f10], ldap[0x55eb48274a50]
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
Trace: sh[0x55eb482586a0], connected[1], ops[0x55eb482c6f10], ldap[0x55eb48274a50]
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_EXTENDED]
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_done] (0x0040):
ldap_extended_operation result: Operations error(1), Failed to split fully qualified
name.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_done] (0x0040):
ldap_extended_operation failed, server logs might contain more details.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_op_destructor] (0x2000):
Operation 16 finished
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_get_user_done] (0x0040):
s2n exop request failed.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_done] (0x4000):
releasing operation connection
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_subdomain_account_done]
(0x0040): ipa_get_*_acct request failed: [1432158229]: Network I/O Error.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_done] (0x0400): DP Request
[Account #1]: Request handler finished [0]: Success
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [_dp_req_recv] (0x0400): DP Request
[Account #1]: Receiving request data.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_list_success]
(0x0400): DP Request [Account #1]: Finished. Success.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_std] (0x1000): DP
Request [Account #1]: Returning [Internal Error]: 3,1432158229,Network I/O Error
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_table_value_destructor]
(0x0400): Removing [0:1:0x0001:1:V:domain.edu:name=[e-mail]] from reply table
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_destructor] (0x0400): DP
Request [Account #1]: Request removed.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_destructor] (0x0400): Number
of active DP request: 0
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
Trace: sh[0x55eb482586a0], connected[1], ops[(nil)], ldap[0x55eb48274a50]
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus conn:
0x55eb482d0940
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000):
Dispatching.
(Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_message_handler] (0x2000):
Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
****

The `Returning [Internal Error]: 3,1432158229,Network I/O Error` part sticks out.

[Sumit Bose]

On Fri, Feb 12, 2021 at 10:43:18PM -0000, Mike Conner via FreeIPA-users wrote:
>  More logs. This is from another broken client during an attempt to
> login as an AD user:
>  ****
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sss_domain_get_state] (0x1000):
> Domain domain.edu is Active
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_connect_step] (0x4000):
> reusing cached connection
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_get_acct_info_send]
> (0x0400): Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user
> [S-1-5-21-71189414-1642862984-1097818727-22197] to IPA server
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_send] (0x0400):
> Executing extended operation
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_send] (0x2000):
> ldap_extended_operation sent, msgid = 16
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_op_add] (0x2000): New
> operation 16 timeout 6
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
> Trace: sh[0x55eb482586a0], connected[1], ops[0x55eb482c6f10], ldap[0x55eb48274a50]
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
> Trace: end of ldap_result list
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
> Trace: sh[0x55eb482586a0], connected[1], ops[0x55eb482c6f10], ldap[0x55eb48274a50]
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_message] (0x4000):
> Message type: [LDAP_RES_EXTENDED]
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_done] (0x0040):
> ldap_extended_operation result: Operations error(1), Failed to split fully qualified
> name.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_exop_done] (0x0040):
> ldap_extended_operation failed, server logs might contain more details. 
Hi,

the client sends a lookup request for the SID
S-1-5-21-71189414-1642862984-1097818727-22197 to the server but on the
server side a user or a group which are processed during this request do
not have an '@' character in the name. Did you modify sssd.conf on the
server to return only short names? If that's not the case do you know if
the AD object with SID S-1-5-21-71189414-1642862984-1097818727-22197 has
some '@' characters in the name? And which version of IPA are you using
on the IPA servers?

bye,
Sumit

>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]]
> [sdap_op_destructor] (0x2000): Operation 16 finished
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_s2n_get_user_done] (0x0040):
> s2n exop request failed.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_done] (0x4000):
> releasing operation connection
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [ipa_subdomain_account_done]
> (0x0040): ipa_get_*_acct request failed: [1432158229]: Network I/O Error.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_id_op_destroy] (0x4000):
> releasing operation connection
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_done] (0x0400): DP Request
> [Account #1]: Request handler finished [0]: Success
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [_dp_req_recv] (0x0400): DP Request
> [Account #1]: Receiving request data.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_list_success]
> (0x0400): DP Request [Account #1]: Finished. Success.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_reply_std] (0x1000): DP
> Request [Account #1]: Returning [Internal Error]: 3,1432158229,Network I/O Error
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_table_value_destructor]
> (0x0400): Removing [0:1:0x0001:1:V:domain.edu:name=[e-mail]] from reply table
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_destructor] (0x0400): DP
> Request [Account #1]: Request removed.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [dp_req_destructor] (0x0400):
> Number of active DP request: 0
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
> Trace: sh[0x55eb482586a0], connected[1], ops[(nil)], ldap[0x55eb48274a50]
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sdap_process_result] (0x2000):
> Trace: end of ldap_result list
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000): dbus
> conn: 0x55eb482d0940
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_dispatch] (0x4000):
> Dispatching.
>  (Fri Feb 12 16:35:20 2021) [sssd[be[ipa.domain.edu]]] [sbus_message_handler] (0x2000):
> Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
> /org/freedesktop/sssd/dataprovider
>  ****
>  
>  The `Returning [Internal Error]: 3,1432158229,Network I/O Error` part sticks out.
>  _______________________________________________
>  FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
>  To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
>  Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
>  List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
>  List Archives:
> https://lists.fedorahosted.org/archives/list/[e-mail]...
>  Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Mike Conner]

Yes. I had modified sssd.conf on the server in pursuit of the solution to proposed change
and that is what caused this issue. I reverted the config and authentication/lookups are
now working as expected. I'd forgotten that I made that change and since clients with
in-tact caches were still working the impact wasn't evident until I configured a new
client and enough time had passed that I didn't make the connection. Lesson learned.
Revisiting the logs, I see it was the "Failed to split fully qualified name."
that led you to this conclusion.

I'm tremendously grateful for your help!