Hello!
Today we successfully upgraded our FreeIPA servers from 4.6.4 to 4.6.8
via `yum`.
Other than the upgrade process taking what seemed to be a long time,
it completed without an issue and everything is intact, including the
AD Trust (as stated). We use a naming convention posix-group and
posix-group_external for mapping purposes.
After adding an AD user to an external group, I noticed the following
messages logged in the dirsrv error log:
[08/Apr/2021:13:54:45.582168432 -0400] - ERR - schema-compat-plugin -
group "posix-group(a)ipa.domain" does not exist because SSSD is offline.
The SSSD logs do show that there was a crash:
(2021-04-08 13:54:35): [be[ipa.domain]] [dp_get_account_info_handler]
(0x0200): Got request for
[0x2][BE_REQ_GROUP][name=posix-group(a)ipa.domain]
(2021-04-08 13:54:38): [be[ipa.domain]] [dp_get_account_info_handler]
(0x0200): Got request for [0x1][BE_REQ_USER][name=idm-user(a)ipa.domain]
(2021-04-08 13:54:41): [be[ipa.domain]] [generic_ext_search_handler]
(0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(2021-04-08 13:54:41): [be[ipa.domain]] [sdap_id_op_done] (0x0200):
communication error on cached connection, moving to next server
(2021-04-08 13:54:41): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:41): [be[ipa.domain]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal
status does not necessarily indicate network port issues.
(2021-04-08 13:54:41): [be[ipa.domain]] [get_port_status] (0x0100):
Resetting the status of port 0 for server 'ipa-master.ipa.domain'
(2021-04-08 13:54:41): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:41): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:41): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:41): [be[ipa.domain]] [child_sig_handler] (0x0100):
child [16309] finished successfully.
(2021-04-08 13:54:41): [be[ipa.domain]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
(2021-04-08 13:54:41): [be[ipa.domain]] [sasl_bind_send] (0x0100):
Executing sasl bind mech: GSSAPI, user: host/ipa-master.ipa.domain
(2021-04-08 13:54:47): [be[ipa.domain]] [sasl_bind_send] (0x0020):
ldap_sasl_bind failed (-5)[Timed out]
(2021-04-08 13:54:47): [be[ipa.domain]] [sasl_bind_send] (0x0080):
Extended failure message: [unknown error]
(2021-04-08 13:54:47): [be[ipa.domain]] [sdap_cli_connect_recv]
(0x0040): Unable to establish connection [110]: Connection timed out
(2021-04-08 13:54:47): [be[ipa.domain]] [fo_set_port_status] (0x0100):
Marking port 0 of server 'ipa-master.ipa.domain' as 'not working'
(2021-04-08 13:54:47): [be[ipa.domain]]
[ipa_id_get_account_info_orig_done] (0x0040): sdap_handle_acct request
failed: 110
(2021-04-08 13:54:47): [be[ipa.domain]] [generic_ext_search_handler]
(0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(2021-04-08 13:54:47): [be[ipa.domain]] [sdap_get_users_done]
(0x0040): Failed to retrieve users [110][Connection timed out].
(2021-04-08 13:54:47): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:47): [be[ipa.domain]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal
status does not necessarily indicate network port issues.
(2021-04-08 13:54:47): [be[ipa.domain]] [fo_resolve_service_send]
(0x0020): No available servers for service 'IPA'
(2021-04-08 13:54:47): [be[ipa.domain]] [sdap_id_op_connect_done]
(0x0020): Failed to connect, going offline (5 [Input/output error])
(2021-04-08 13:54:47): [be[ipa.domain]] [be_run_offline_cb] (0x0080):
Going offline. Running callbacks.
(2021-04-08 13:54:47): [be[ipa.domain]]
[ipa_id_get_account_info_orig_done] (0x0040): sdap_handle_acct request
failed: 11
(2021-04-08 13:54:48): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:48): [be[ipa.domain]]
[resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record
of 'ipa-master.ipa.domain' in files
(2021-04-08 13:54:48): [be[ipa.domain]] [set_server_common_status]
(0x0100): Marking server 'ipa-master.ipa.domain' as 'resolving name'
(2021-04-08 13:54:48): [be[ipa.domain]] [set_server_common_status]
(0x0100): Marking server 'ipa-master.ipa.domain' as 'name resolved'
(2021-04-08 13:54:48): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:48): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:48): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:48): [be[ipa.domain]] [child_sig_handler] (0x0100):
child [16320] finished successfully.
(2021-04-08 13:54:48): [be[ipa.domain]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
(2021-04-08 13:54:48): [be[ipa.domain]] [sasl_bind_send] (0x0100):
Executing sasl bind mech: GSSAPI, user: host/ipa-master.ipa.domain
(2021-04-08 13:54:48): [be[ipa.domain]] [fo_set_port_status] (0x0100):
Marking port 0 of server 'ipa-master.ipa.domain' as 'working'
(2021-04-08 13:54:48): [be[ipa.domain]] [set_server_common_status]
(0x0100): Marking server 'ipa-master.ipa.domain' as 'working'
(2021-04-08 13:54:48): [be[ipa.domain]] [be_run_online_cb] (0x0080):
Going online. Running callbacks.
(2021-04-08 13:54:48): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:48): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:48): [be[ipa.domain]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 13:54:48): [be[ipa.domain]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master.ipa.domain: [IP] TTL
7200
(2021-04-08 13:54:48): [be[ipa.domain]] [child_sig_handler] (0x0100):
child [16321] finished successfully.
(2021-04-08 13:54:48): [be[ipa.domain]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
(2021-04-08 13:54:56): [be[ipa.domain]] [resolve_srv_send] (0x0200):
The status of SRV lookup is resolved
(2021-04-08 13:54:56): [be[ipa.domain]] [child_sig_handler] (0x0100):
child [16334] finished successfully.
(2021-04-08 13:54:56): [be[ipa.domain]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
The messages appear to be harmless in the sense that the AD user is
associated with their groups correctly and are able to access group
protected resources without an issue.
Searching for the same dirsrv error message via Google and the mailing
list only produces the following URL's, and I didn't experience any
crashes during the upgrade process. Other than it taking about ~25
minutes per server (maybe due to SSSD running during the upgrade?),
everything restarted as expected:
https://bugzilla.redhat.com/show_bug.cgi?id=1346735
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedoraho...
The nsslapd-pluginEnabled has been enabled this entire time.
Looking a little deeper now, I did rename a group post upgrade and
there was a similar set of logs:
[08/Apr/2021:12:03:18.692100370 -0400] - ERR - schema-compat-plugin -
group "pi_posix-group-originalname(a)ipa.domain" does not exist because
SSSD is offline.
[08/Apr/2021:12:03:36.825433630 -0400] - ERR - schema-compat-plugin -
group "pi_posix-group-newname(a)ipa.domain" does not exist because SSSD
is offline.
And the correlated SSSD logs:
(2021-04-08 12:03:08): [be[rc.usf.edu]] [dp_get_account_info_handler]
(0x0200): Got request for
[0x2][BE_REQ_GROUP][name=pi_posix-group-originalname@ipadomain]
(2021-04-08 12:03:09): [be[rc.usf.edu]] [dp_get_account_info_handler]
(0x0200): Got request for [0x1][BE_REQ_USER][name=idm-user]
(2021-04-08 12:03:14): [be[rc.usf.edu]] [generic_ext_search_handler]
(0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(2021-04-08 12:03:14): [be[rc.usf.edu]] [sdap_id_op_done] (0x0200):
communication error on cached connection, moving to next server
(2021-04-08 12:03:14): [be[rc.usf.edu]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 12:03:14): [be[rc.usf.edu]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal
status does not necessarily indicate network port issues.
(2021-04-08 12:03:14): [be[rc.usf.edu]] [get_port_status] (0x0100):
Resetting the status of port 0 for server 'ipa-master'
(2021-04-08 12:03:14): [be[rc.usf.edu]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master: [IP] TTL 7200
(2021-04-08 12:03:14): [be[rc.usf.edu]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 12:03:14): [be[rc.usf.edu]] [be_resolve_server_process]
(0x0200): Found address for server ipa-master: [IP] TTL 7200
(2021-04-08 12:03:15): [be[rc.usf.edu]] [generic_ext_search_handler]
(0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(2021-04-08 12:03:15): [be[rc.usf.edu]] [sdap_get_users_done]
(0x0040): Failed to retrieve users [110][Connection timed out].
(2021-04-08 12:03:18): [be[rc.usf.edu]] [dp_get_account_info_handler]
(0x0200): Got request for [0x1][BE_REQ_USER][name=user@ad-domain]
(2021-04-08 12:03:18): [be[rc.usf.edu]] [child_sig_handler] (0x0100):
child [5193] finished successfully.
(2021-04-08 12:03:18): [be[rc.usf.edu]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
(2021-04-08 12:03:18): [be[rc.usf.edu]] [sasl_bind_send] (0x0100):
Executing sasl bind mech: GSSAPI, user: host/ipa-master
(2021-04-08 12:03:19): [be[rc.usf.edu]] [fo_set_port_status] (0x0100):
Marking port 0 of server 'ipa-master' as 'working'
(2021-04-08 12:03:19): [be[rc.usf.edu]] [set_server_common_status]
(0x0100): Marking server 'ipa-master' as 'working'
(2021-04-08 12:03:30): [be[rc.usf.edu]] [dp_get_account_info_handler]
(0x0200): Got request for
[0x2][BE_REQ_GROUP][name=pi_posix-group-newname@ipadomain]
(2021-04-08 12:03:36): [be[rc.usf.edu]] [generic_ext_search_handler]
(0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(2021-04-08 12:03:36): [be[rc.usf.edu]] [sdap_id_op_done] (0x0200):
communication error on cached connection, moving to next server
(2021-04-08 12:03:36): [be[rc.usf.edu]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'IPA'
(2021-04-08 12:03:36): [be[rc.usf.edu]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal
status does not necessarily indicate network port issues.
(2021-04-08 12:03:36): [be[rc.usf.edu]] [fo_resolve_service_send]
(0x0020): No available servers for service 'IPA'
(2021-04-08 12:03:36): [be[rc.usf.edu]] [sdap_id_op_connect_done]
(0x0020): Failed to connect, going offline (5 [Input/output error])
Has anyone else run into this issue? Can the messages be ignored? Are
there any steps to take to resolve the issue?
Thank you,
John DeSantis