Hi dear freeipa-users :D
I am currently testing FreeIPA in a Windows Active Directory environment.
The goal is to use this as a productive secondary domain with a one-way trust from AD to
FreeIPA. (We have lots of developers that work with Linux clients (Fedora and CentOS)
aswell as want to profit from their already existing user account in the AD environment.
This will also make it easier for the IT to track which clients/vms etc. are domain joined
and which are not and would allow us to restrict them slightly on our systems.)
I did the installation following the manual on the Freeipa page.
After that i had to troubleshoot why AD users are not getting correct UID/GID assigned
from AD -->
https://www.reddit.com/r/linuxadmin/comments/dcb1xh/freeipa_and_windows_a...
I fixed that by doing the said thing by deleting established trust, re-adding trust with
correct parameters, deleting sssd cache.
Now im facing something else that gives me a headache since a few days.
I am unable to login to AD users from IPA joined Client.
ipa-client-install etc. done. and should be fine.
But im unable to su to user, or ssh, or get infos with ID or getent passwd user.
I can kinit into said user though from client, thats why im guessing that ipa-client
install worked.
And from ipa server off, im also able to login to the user like intended (ssh, su, getent,
id works all fine).
I added debug_level 9 to sssd but im unable to identify the problem.
I pasted down below said log file aswell as the krb5.conf and sssd.conf if there is
anything wrong.
AD domain is: domain.ad
IPA domain is: domain.test
User: user
I hope someone can help me here :)
Best regards,
Dani
sssd.conf
[domain/domain.test]
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = domain.test
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = ipa-client.domain.test
chpass_provider = ipa
ipa_server = _srv_, ipa.domain.test
ldap_tls_cacert = /etc/ipa/ca.crt
debug_level = 9
[sssd]
services = nss, sudo, pam, ssh
domains = domain.test
debug_level = 9
[nss]
homedir_substring = /home
debug_level = 9
[pam]
debug_level = 9
[sudo]
debug_level = 9
[autofs]
[ssh]
debug_level = 9
[pac]
[ifp]
[secrets]
[session_recording]
krb5.conf
#File modified by ipa-client-install
includedir /etc/krb5.conf.d/
includedir /var/lib/sss/pubconf/krb5.include.d/
[libdefaults]
default_realm = domain.TEST
dns_lookup_realm = true
dns_lookup_kdc = true
rdns = false
dns_canonicalize_hostname = false
ticket_lifetime = 24h
forwardable = true
udp_preference_limit = 0
default_ccache_name = KEYRING:persistent:%{uid}
[realms]
domain.TEST = {
pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem
pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem
auth_to_local = RULE:[1:$1@$0](^.*@DOMAIN.AD$)s/@DOMAIN.AD/@domain.ad/
auth_to_local = DEFAULT
}
[domain_realm]
.domain.test = domain.TEST
domain.test = domain.TEST
ipa-client.domain.test = domain.TEST
.DOMAIN.ad = domain.AD
domain.ad = domain.AD
ad-test.domain.ad = domain.AD
Logfile: /var/log/sssd/sssd_domain
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [ldb] (0x4000): commit ldb transaction
(nesting: 0)
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [ipa_sudo_full_refresh_done] (0x0400):
Successful full refresh of sudo rules
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [be_ptask_done] (0x0400): Task [SUDO
Full Refresh]: finished successfully
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [be_ptask_schedule] (0x0400): Task
[SUDO Full Refresh]: scheduling task 21600 seconds from last execution time [1572030495]
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[(nil)], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:15 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): dbus conn:
0x55a487f6a870
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_message_handler] (0x2000):
Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_get_sender_id_send] (0x2000): Not
a sysbus message, quit
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_get_account_info_handler] (0x0200):
Got request for [0x1][BE_REQ_USER][name=user(a)domain.ad]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): DP Request
[Account #4]: New request. Flags [0x0001].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): Number of
active DP request: 1
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_get_ad_override_connect_done]
(0x4000): Searching for overrides in view [Default Trust View] with filter
[(&(objectClass=ipaUserOverride)(uid=user))].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_print_server] (0x2000): Searching
192.168.14.60:389
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=user))][cn=Default
Trust View,cn=views,cn=accounts,dc=domain,dc=test].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x2000):
ldap_search_ext called, msgid = 18
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_add] (0x2000): New operation
18 timeout 6
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[0x55a487f7e000], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_destructor] (0x2000):
Operation 18 finished
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_get_ad_override_done] (0x4000): No
override found with filter [(&(objectClass=ipaUserOverride)(uid=user))].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_get_acct_info_send] (0x0400):
Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user [user] to IPA server
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_send] (0x0400): Executing
extended operation
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 19
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_add] (0x2000): New operation
19 timeout 6
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[0x55a487fac5d0], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[0x55a487fac5d0], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_EXTENDED]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_done] (0x0040):
ldap_extended_operation result: No such object(32), (null).
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_destructor] (0x2000):
Operation 19 finished
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f92830
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f92900
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f92830 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f92900 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f92830 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_search_by_name] (0x0400): No
such entry
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_cache_search_groups] (0x2000):
Search groups with filter: (&(objectCategory=group)(ghost=user(a)domain.ad))
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f7d500
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f7d5d0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f7d500 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f7d5d0 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f7d500 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_cache_search_groups] (0x2000):
No such entry
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_delete_user] (0x0400): Error: 2
(No such file or directory)
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_done] (0x4000): releasing
operation connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_done] (0x0400): DP Request
[Account #4]: Request handler finished [0]: Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [_dp_req_recv] (0x0400): DP Request
[Account #4]: Receiving request data.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_list_success] (0x0400):
DP Request [Account #4]: Finished. Success.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_std] (0x1000): DP Request
[Account #4]: Returning [Success]: 0,0,Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:1::domain.ad:name=user@domain.ad] from reply table
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): DP
Request [Account #4]: Request removed.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[(nil)], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): dbus conn:
0x55a487f6a870
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_message_handler] (0x2000):
Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_get_sender_id_send] (0x2000): Not
a sysbus message, quit
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_get_account_info_handler] (0x0200):
Got request for [0x1][BE_REQ_USER][name=user(a)domain.ad]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): DP Request
[Account #5]: New request. Flags [0x0001].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): Number of
active DP request: 1
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_search_user_next_base] (0x0400):
Searching for users with base [cn=accounts,dc=domain,dc=test]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_print_server] (0x2000): Searching
192.168.14.60:389
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x0400):
calling ldap_search_ext with
[(&(|(krbPrincipalName=user@domain.ad)(mail=user@domain.ad)(krbPrincipalName=user\\@domain.ad@domain.TEST))(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=domain,dc=test].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [objectClass]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uid]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userPassword]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [uidNumber]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gidNumber]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [gecos]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [homeDirectory]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginShell]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPrincipalName]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [cn]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [memberOf]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [ipaUniqueID]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [ipaNTSecurityIdentifier]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [modifyTimestamp]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [entryUSN]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowLastChange]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMin]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowMax]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowWarning]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowInactive]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowExpire]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [shadowFlag]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbLastPwdChange]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [krbPasswordExpiration]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [pwdAttribute]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [authorizedService]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [accountExpires]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userAccountControl]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [nsAccountLock]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [host]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginDisabled]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginExpirationTime]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [ipaSshPubKey]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [ipaUserAuthType]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [userCertificate;binary]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x1000):
Requesting attrs: [mail]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_ext_step] (0x2000):
ldap_search_ext called, msgid = 20
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_add] (0x2000): New operation
20 timeout 6
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[0x55a487f7dc70], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_destructor] (0x2000):
Operation 20 finished
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_search_user_process] (0x0400):
Search for users, returned 0 results.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_search_user_process] (0x2000):
Retrieved total 0 users
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_done] (0x4000): releasing
operation connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f97290
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f97360
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f97290 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f97360 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f97290 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_search_by_name] (0x0400): No
such entry
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_cache_search_groups] (0x2000):
Search groups with filter: (&(objectCategory=group)(ghost=user(a)domain.ad))
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f96800
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f968d0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f96800 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f968d0 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f96800 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_cache_search_groups] (0x2000):
No such entry
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_delete_user] (0x0400): Error: 2
(No such file or directory)
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f72da0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f72e70
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f72da0 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f72e70 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f72da0 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_search_user_by_upn] (0x0400): No
entry with upn [user(a)domain.ad] found.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_id_get_account_info_orig_done]
(0x0080): Object not found, ending request
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_done] (0x0400): DP Request
[Account #5]: Request handler finished [0]: Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [_dp_req_recv] (0x0400): DP Request
[Account #5]: Receiving request data.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_list_success] (0x0400):
DP Request [Account #5]: Finished. Success.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_std] (0x1000): DP Request
[Account #5]: Returning [Success]: 0,0,Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:1:U:domain.test:name=user@domain.ad] from reply table
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): DP
Request [Account #5]: Request removed.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[(nil)], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): dbus conn:
0x55a487f6a870
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_message_handler] (0x2000):
Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sbus_get_sender_id_send] (0x2000): Not
a sysbus message, quit
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_get_account_info_handler] (0x0200):
Got request for [0x1][BE_REQ_USER][name=user(a)domain.ad]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): DP Request
[Account #6]: New request. Flags [0x0001].
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_attach_req] (0x0400): Number of
active DP request: 1
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.test is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sss_domain_get_state] (0x1000): Domain
domain.ad is Active
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_connect_step] (0x4000):
reusing cached connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_get_acct_info_send] (0x0400):
Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user [user(a)domain.ad] to IPA
server
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_send] (0x0400): Executing
extended operation
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 21
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_add] (0x2000): New operation
21 timeout 6
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[0x55a487f7d750], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_EXTENDED]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ipa_s2n_exop_done] (0x0040):
ldap_extended_operation result: No such object(32), (null).
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_op_destructor] (0x2000):
Operation 21 finished
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x55a487f97630
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x55a487f97700
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Running timer event
0x55a487f97630 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f97700 "ltdb_timeout"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [ldb] (0x4000): Destroying timer event
0x55a487f97630 "ltdb_callback"
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sysdb_search_user_by_upn] (0x0400): No
entry with upn [user(a)domain.ad] found.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_id_op_done] (0x4000): releasing
operation connection
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_done] (0x0400): DP Request
[Account #6]: Request handler finished [0]: Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [_dp_req_recv] (0x0400): DP Request
[Account #6]: Receiving request data.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_list_success] (0x0400):
DP Request [Account #6]: Finished. Success.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_reply_std] (0x1000): DP Request
[Account #6]: Returning [Success]: 0,0,Success
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:1:U:domain.ad:name=user@domain.ad] from reply table
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): DP
Request [Account #6]: Request removed.
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
sh[0x55a487f69200], connected[1], ops[(nil)], ldap[0x55a487f688d0]
(Fri Oct 25 15:08:44 2019) [sssd[be[domain.test]]] [sdap_process_result] (0x2000): Trace:
end of ldap_result list