I have attached some sssd logs snippets with debug_level activated in sssd.conf (some
lines have been truncated) :
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [dp_get_account_info_send] (0x0200): Got
request for [0x1][BE_REQ_USER][name=test_user(a)example.com]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [dp_attach_req] (0x0400): DP Request
[Account #1]: New request. Flags [0x0001].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [dp_attach_req] (0x0400): Number of
active DP request: 1
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
ipa.example.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
EXAMPLE.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
ipa.example.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
EXAMPLE.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_get_ad_override_connect_done]
(0x4000): Searching for overrides in view [Default Trust View] with filter
[(&(objectClass=ipaUserOverride)(uid=test_user))].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_print_server] (0x2000): Searching
10.10.100.121:389
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(objectClass=ipaUserOverride)(uid=test_user))][cn=Default Trust
View,cn=views,cn=accounts,dc=
ipa,dc=example,dc=com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_get_generic_ext_step] (0x2000):
ldap_search_ext called, msgid = 16
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_op_add] (0x2000): New operation 16
timeout 6
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x55756a96b460], connected[1], ops[0x55756a964f90], ldap[0x55756a9618f0]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_message] (0x4000): Message
type: [LDAP_RES_SEARCH_ENTRY]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_entry] (0x1000): OriginalDN:
[ipaanchoruuid=:SID:S-1-5-21-1695049048-159329179-1862793928-25318,cn=Default Trust
View,cn=views,cn=accounts,dc=ipa,d
c=example,dc=com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [ipaSshPubKey]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [ipaAnchorUUID]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [uid]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [uidNumber]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectClass]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_parse_range] (0x2000): No
sub-attributes for [ipaOriginalUid]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x55756a96b460], connected[1], ops[0x55756a964f90], ldap[0x55756a9618f0]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_message] (0x4000): Message
type: [LDAP_RES_SEARCH_RESULT]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_get_generic_op_finished] (0x0400):
Search result: Success(0), no errmsg set
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_op_destructor] (0x2000): Operation
16 finished
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_get_ad_override_done] (0x4000):
Found override for object with filter
[(&(objectClass=ipaUserOverride)(uid=test_user))].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_id_op_destroy] (0x4000): releasing
operation connection
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_subdomain_account_got_override]
(0x4000): Processing override.
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
ipa.example.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
EXAMPLE.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_get_acct_info_send] (0x0400):
Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user
[S-1-5-21-1695049048-159329179-1862793928-25318] to IPA ser
ver
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_exop_send] (0x0400): Executing
extended operation
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 17
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_op_add] (0x2000): New operation 17
timeout 6
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x55756a96b460], connected[1], ops[0x55756a9609a0], ldap[0x55756a9618f0]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_result] (0x2000): Trace:
sh[0x55756a96b460], connected[1], ops[0x55756a9609a0], ldap[0x55756a9618f0]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_process_message] (0x4000): Message
type: [LDAP_RES_EXTENDED]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sdap_op_destructor] (0x2000): Operation
17 finished
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sss_domain_get_state] (0x1000): Domain
EXAMPLE.com is Active
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [add_v1_user_data] (0x4000): BER tag is
[48]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Found new
sequence.
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [objectSIDString].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADname].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADuidNumber].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADgidNumber].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADhomeDirectory].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADgecos].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalADloginShell].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [userPrincipalName].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [defaultOverrideName].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [adAccountExpires].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [adUserAccountControl].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [sshPublicKey].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [mail].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalDN].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [get_extra_attrs] (0x4000): Extra
attribute [originalMemberOf]
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_get_user_done] (0x0400):
Received [44] groups in group list from IPA Server
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_get_user_done] (0x0400):
[test_user(a)example.com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_get_user_done] (0x0400):
[infra_admins(a)ipa.example.com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_get_user_done] (0x0400):
[unix_users(a)ipa.example.com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_save_objects] (0x4000): Found
original AD name [test_user(a)example.com].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ipa_s2n_save_objects] (0x4000): Found
original AD upn [test.user(a)COMPANY.COM].
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): start ldb transaction
(nesting: 0)
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): start ldb transaction
(nesting: 1)
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Added timed event
"ldb_kv_callback": 0x55756a9ca910
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Added timed event
"ldb_kv_timeout": 0x55756a9aad60
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Running timer event
0x55756a9ca910 "ldb_kv_callback"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Destroying timer event
0x55756a9aad60 "ldb_kv_timeout"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Destroying timer event
0x55756a9ca910 "ldb_kv_callback"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_search_by_name] (0x0400): No such
entry
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_store_user] (0x1000): User
test_user(a)example.com does not exist.
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_add_user] (0x0040): Group named
test_user(a)example.com already exists in an MPG domain
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_add_user] (0x0400): Error: 17
(File exists)
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): cancel ldb transaction
(nesting: 2)
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Added timed event
"ldb_kv_callback": 0x55756a9ca910
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Added timed event
"ldb_kv_timeout": 0x55756a9aad60
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Running timer event
0x55756a9ca910 "ldb_kv_callback"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Destroying timer event
0x55756a9aad60 "ldb_kv_timeout"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): Destroying timer event
0x55756a9ca910 "ldb_kv_callback"
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_search_user_by_uid] (0x0400): No
such entry
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_delete_user] (0x0400): Error: 2
(No such file or directory)
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [sysdb_store_user] (0x0040): Cache update
failed: 17
(Tue Jun 15 16:09:02 2021) [be[ipa.example.com]] [ldb] (0x4000): cancel ldb transaction
(nesting: 1)