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_ad_u...
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@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@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@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@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@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@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@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@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
On ma, 28 loka 2019, Danijel Bojic via FreeIPA-users wrote:
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_ad_u...
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.
kinit with AD user has nothing to do with FreeIPA. You talk to AD DCs here, avoiding FreeIPA infra.
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.
The log below is only for SSSD on IPA client. The log shows that the client asked IPA master to resolve AD users and that one failed. But you haven't provided SSSD logs for the same timeframe from IPA master.
See here: https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html#common-ipa-prov...
(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@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
One thing to check which was our problem when we first implemented this is that every user must have a gidNumber assigned and that gidNumber has to be assigned to a group existing in AD (might work if the group is just in IPA, never tested that). Also, all of the groups that a user is a member of need to have a gidNumber assigned in AD. That fixed the vast majority of our issues when first implementing.
— Bob Jones Lead Linux Services Engineer ITS ECP - Linux Services
On Oct 28, 2019, at 4:52 AM, Alexander Bokovoy via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On ma, 28 loka 2019, Danijel Bojic via FreeIPA-users wrote:
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_ad_u...
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.
kinit with AD user has nothing to do with FreeIPA. You talk to AD DCs here, avoiding FreeIPA infra.
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.
The log below is only for SSSD on IPA client. The log shows that the client asked IPA master to resolve AD users and that one failed. But you haven't provided SSSD logs for the same timeframe from IPA master.
See here: https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html#common-ipa-prov...
(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@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
-- / Alexander Bokovoy Sr. Principal Software Engineer Security / Identity Management Engineering Red Hat Limited, Finland _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@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/freeipa-users@lists.fedorahoste...
Hi Alexander
Thanks for clarifying.
I don't see anything in the sssd_domain.log I see something though in the sssd_nss.log file. I crosschecked my sssd.conf file and corrected some spelling error and it seems to work now. I can su and ssh with the AD Domain users on the ipa client. Only thing now is that when i try to login in the gui, it just restarts the gui. Maybe you have an idea what to look into with this issue. Here's the output of nss.log:
(Mon Oct 28 16:42:46 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #486: This request type does not support filtering result by negative cache (Mon Oct 28 16:42:46 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #486: Returning updated object [user@domain.ad] (Mon Oct 28 16:42:46 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #486: Found 1 entries in domain domain.ad (Mon Oct 28 16:42:46 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:1:user@domain.ad@domain.ad] (Mon Oct 28 16:42:46 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #486: Finished: Success (Mon Oct 28 16:42:46 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:42:46 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:16 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a642f0][21] (Mon Oct 28 16:43:16 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a55990][22] (Mon Oct 28 16:43:16 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a626b0][23] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[997] egid[992] pid[2279]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a64ec0][24] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #487: Setting "Object by name" plugin (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #487: New request 'Object by name' (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #487: Parsing input name [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user@domain.ad' matched expression for domain 'domain.ad', user is user (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #487: Setting name [user] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #487: Performing a single domain search (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #487: Search will check the cache and check the data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #487: Using domain [domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #487: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #487: Looking up user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #487: Checking negative cache for [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #487: [user@domain.ad] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #487: Looking up [user@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a60440
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a60510
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a60440 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60510 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60440 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a665c0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66690
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a665c0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66690 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a665c0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #487: Returning [user@domain.ad] from cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #487: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #487: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #487: Finished: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #488: Setting "Initgroups by name" plugin (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #488: New request 'Initgroups by name' (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #488: Parsing input name [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user@domain.ad' matched expression for domain 'domain.ad', user is user (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #488: Setting name [user] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #488: Performing a single domain search (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #488: Search will check the cache and check the data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #488: Using domain [domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #488: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #488: Looking up user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #488: Checking negative cache for [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #488: [user@domain.ad] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #488: Looking up [user@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a661d0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a662a0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a661d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a662a0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a661d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5afc0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5b090
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b090 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a66070
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66140
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a66070 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a500
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a5d0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66140 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66070 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a500 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6aeb0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6af80
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5d0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a500 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6aeb0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6af80 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6aeb0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #488: Object found, but needs to be refreshed. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #488: Looking up [user@domain.ad] in data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:3:user@domain.ad@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.ad][0x3][BE_REQ_INITGROUPS][name=user@domain.ad:-] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a54e70 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:3:user@domain.ad@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a54e70 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.nss.MemoryCache.UpdateInitgroups on path /org/freedesktop/sssd/nss/memcache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_memorycache_update_initgroups] (0x1000): Updating initgroups memory cache of [user@domain.ad@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6cb60
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6cc30
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6cb60 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6cc30 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6cb60 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5b080
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6cb60
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5b080 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6cb60 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b080 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a69c40
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a69d10
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a69c40 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a710e0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a711b0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69d10 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69c40 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a710e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a71a20
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a71af0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a711b0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a710e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a71a20 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a71af0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a71a20 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #488: Looking up [user@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a64dc0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a70210
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a64dc0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a70210 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a64dc0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a67c60
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a69ee0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a67c60 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69ee0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67c60 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a645d0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a646a0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a645d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a707e0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a708b0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a646a0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a645d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a707e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a71120
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a711f0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a708b0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a707e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a71120 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a711f0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a71120 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #488: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #488: Returning updated object [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #488: Found 3 entries in domain domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:3:user@domain.ad@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #488: Finished: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 500 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #489: Setting "Group by ID" plugin (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #489: New request 'Group by ID' (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #489: Performing a multi-domain search (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #489: Search will check the cache and check the data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.test type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #489: Using domain [domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #489: Looking up GID:500@domain.test (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #489: Checking negative cache for [GID:500@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.test/500] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/500] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #489: [GID:500@domain.test] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Looking up [GID:500@domain.test] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a62920
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a629f0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a62920 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a629f0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62920 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Object [GID:500@domain.test] was not found in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #489: Looking up [GID:500@domain.test] in data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:2:500@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.test][0x2][BE_REQ_GROUP][idnumber=500:-] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a551a0 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:2:500@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a551a0 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Looking up [GID:500@domain.test] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5fa20
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5f5c0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5fa20 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5f5c0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5fa20 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Object [GID:500@domain.test] was not found in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_add_to_domain] (0x0400): CR #489: Adding [GID:500@domain.test] to negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GID/domain.test/500] to negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #489: Using domain [domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #489: Looking up GID:500@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #489: Checking negative cache for [GID:500@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.ad/500] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/500] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #489: [GID:500@domain.ad] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Looking up [GID:500@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5f960
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5fa30
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5f960 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5fa30 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5f960 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a63e40
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5f960
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a63e40 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5f960 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a63e40 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a59640
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a57c60
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a59640 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a57c60 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a59640 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_get_user_members_recursively] (0x0400): No such entry (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #489: Object found, but needs to be refreshed. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #489: Looking up [GID:500@domain.ad] in data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:2:500@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.ad][0x2][BE_REQ_GROUP][idnumber=500:-] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a52d40 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:2:500@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:2:500@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a52d40 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #489: Looking up [GID:500@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a60090
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a59580
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a59580 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a60090
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a63d10
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a63d10 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a59580
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66d40
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a59580 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66d40 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a59580 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a870
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a58060
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a870 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a58060 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a870 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a60090
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66d40
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66d40 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60090 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [user@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [one@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #489: Filtering out results by negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/domain.ad/tester@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #489: Returning updated object [GID:500@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #489: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:2:500@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #489: Finished: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/one@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 1095200010 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #490: Setting "Group by ID" plugin (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #490: New request 'Group by ID' (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #490: Performing a multi-domain search (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #490: Search will check the cache and check the data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.test type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #490: Using domain [domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #490: Looking up GID:1095200010@domain.test (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #490: Checking negative cache for [GID:1095200010@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.test/1095200010] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/1095200010] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #490: [GID:1095200010@domain.test] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #490: Looking up [GID:1095200010@domain.test] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a62030
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a62100
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a62030 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62100 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62030 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a290
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a601b0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a290 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a601b0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a290 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5f8f0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5f9c0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5f8f0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5f9c0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5f8f0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a5e0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a68dd0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a5e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a68dd0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a5e0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a683c0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a5e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a683c0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5e0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [one@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [user@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #490: Object found, but needs to be refreshed. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #490: Looking up [GID:1095200010@domain.test] in data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:2:1095200010@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.test][0x2][BE_REQ_GROUP][idnumber=1095200010:-] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a69180 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:2:1095200010@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a69180 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #490: Looking up [GID:1095200010@domain.test] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6aec0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66390
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6aec0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66390 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6aec0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a595d0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6aae0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6aae0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a69fe0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a59510
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a69fe0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a59510 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69fe0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a57f50
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a5c0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a57f50 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5c0 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a57f50 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6bb30
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a57f50
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6bb30 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a57f50 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6bb30 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [one@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [user@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #490: Filtering out results by negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/domain.test/ad_groups@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #490: Returning updated object [GID:1095200010@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #490: Found 1 entries in domain domain.test (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:2:1095200010@domain.test] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #490: Finished: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.test/one@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.test/user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #491: Setting "Object by name" plugin (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #491: New request 'Object by name' (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #491: Parsing input name [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user@domain.ad' matched expression for domain 'domain.ad', user is user (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #491: Setting name [user] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #491: Performing a single domain search (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #491: Search will check the cache and check the data provider (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #491: Using domain [domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #491: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #491: Looking up user@domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #491: Checking negative cache for [user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/user@domain.ad] (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #491: [user@domain.ad] is not present in negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #491: Looking up [user@domain.ad] in cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a140
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a210
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a140 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a210 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a140 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a628a0
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a62970
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a628a0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62970 "ltdb_timeout"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a628a0 "ltdb_callback"
(Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #491: Returning [user@domain.ad] from cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #491: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #491: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:27 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #491: Finished: Success (Mon Oct 28 16:43:27 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: tester@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #492: Setting "Object by name" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #492: New request 'Object by name' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #492: Parsing input name [tester@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'tester@domain.ad' matched expression for domain 'domain.ad', user is tester (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #492: Setting name [tester] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #492: Performing a single domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #492: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #492: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #492: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #492: Looking up tester@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #492: Checking negative cache for [tester@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/tester@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/domain.ad/tester@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #492: [tester@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #492: Looking up [tester@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a070
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a140
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a070 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a140 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a070 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a64640
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a64710
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a64640 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a64710 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a64640 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #492: Returning [tester@domain.ad] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #492: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #492: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #492: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_parse_sid] (0x4000): Input SID [S-1-5-21-2588721784-3601702760-1703444798-1112] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_sid] (0x0400): Input SID: S-1-5-21-2588721784-3601702760-1703444798-1112 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #493: Setting "Object by SID" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #493: New request 'Object by SID' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_object_by_sid_well_known] (0x4000): CR #493: SID [S-1-5-21-2588721784-3601702760-1703444798-1112] is not a Well-Known SID. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #493: Performing a multi-domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #493: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.test type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #493: Using domain [domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #493: Looking up SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #493: Checking negative cache for [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/SID/S-1-5-21-2588721784-3601702760-1703444798-1112] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #493: [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #493: Looking up [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a610
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a6e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a610 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a6e0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a610 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_search_object_attr] (0x0400): No such entry. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #493: Object [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] was not found in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #493: Looking up [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] in data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:6:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.test][0x11][BE_REQ_BY_SECID][secid=S-1-5-21-2588721784-3601702760-1703444798-1112:-] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a5f1a0 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:6:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a5f1a0 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #493: Looking up [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5afc0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5b090
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b090 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_search_object_attr] (0x0400): No such entry. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #493: Object [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] was not found in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_add_to_domain] (0x2000): CR #493: This request type does not support negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #493: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #493: Looking up SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #493: Checking negative cache for [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/SID/S-1-5-21-2588721784-3601702760-1703444798-1112] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #493: [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #493: Looking up [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a68210
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a682e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a68210 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a682e0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a68210 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a689c0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a68a90
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a689c0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a68a90 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a689c0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #493: Returning [SID:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.ad] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #493: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:6:S-1-5-21-2588721784-3601702760-1703444798-1112@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #493: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #493: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #494: Setting "User by name" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #494: New request 'User by name' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #494: Parsing input name [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'one@domain.ad' matched expression for domain 'domain.ad', user is one (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #494: Setting name [one] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #494: Performing a single domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #494: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #494: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #494: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #494: Looking up one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #494: Checking negative cache for [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #494: [one@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #494: Looking up [one@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5afc0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5b090
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b090 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a67e60
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a67f30
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a67e60 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67f30 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67e60 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #494: Returning [one@domain.ad] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #494: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #494: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #494: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #495: Setting "Object by name" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #495: New request 'Object by name' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #495: Parsing input name [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'one@domain.ad' matched expression for domain 'domain.ad', user is one (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #495: Setting name [one] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #495: Performing a single domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #495: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #495: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #495: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #495: Looking up one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #495: Checking negative cache for [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #495: [one@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #495: Looking up [one@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a070
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a140
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a070 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a140 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a070 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a62a10
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a69b60
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a62a10 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69b60 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62a10 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #495: Returning [one@domain.ad] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #495: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #495: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #495: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #496: Setting "Initgroups by name" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #496: New request 'Initgroups by name' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #496: Parsing input name [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'one@domain.ad' matched expression for domain 'domain.ad', user is one (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #496: Setting name [one] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #496: Performing a single domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #496: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #496: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #496: Preparing input data for domain [domain.ad] rules (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #496: Looking up one@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #496: Checking negative cache for [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #496: [one@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #496: Looking up [one@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5afc0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5b090
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b090 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a595d0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a67ed0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67ed0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a595d0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a69c80
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6af00
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6afd0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69c80 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a595d0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6af00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6b840
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6b910
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6afd0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6af00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6b840 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6d9e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6dab0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6b910 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6b840 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6d9e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6dab0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6d9e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #496: Object found, but needs to be refreshed. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #496: Looking up [one@domain.ad] in data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x556495a41530:3:one@domain.ad@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [domain.ad][0x3][BE_REQ_INITGROUPS][name=one@domain.ad:-] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x556496a551a0 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x556495a41530:3:one@domain.ad@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x556496a551a0 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.nss.MemoryCache.UpdateInitgroups on path /org/freedesktop/sssd/nss/memcache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_memorycache_update_initgroups] (0x1000): Updating initgroups memory cache of [one@domain.ad@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a250
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a620b0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a250 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a620b0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a250 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5afc0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a5b090
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5b090 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5afc0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a66c00
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a66cd0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a66c00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a72b30
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a72c00
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66cd0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a66c00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a72b30 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a73470
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a73540
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a72c00 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a72b30 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a73470 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a73540 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a73470 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #496: Looking up [one@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a60630
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a62c20
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a60630 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a62c20 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60630 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a69db0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6dd00
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a69db0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6dd00 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69db0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a810
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6abd0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a810 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a71c00
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a71cd0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6abd0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a810 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a71c00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a725b0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a72680
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a71cd0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a71c00 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a725b0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a72680 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a725b0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #496: This request type does not support filtering result by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #496: Returning updated object [one@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #496: Found 3 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x556495a41530:3:one@domain.ad@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #496: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x556496a53e10 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 500 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #497: Setting "Group by ID" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #497: New request 'Group by ID' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #497: Performing a multi-domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #497: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.test type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #497: Using domain [domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #497: Looking up GID:500@domain.test (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #497: Checking negative cache for [GID:500@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.test/500] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #497: [GID:500@domain.test] does not exist (negative cache) (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.ad type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #497: Using domain [domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #497: Looking up GID:500@domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #497: Checking negative cache for [GID:500@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.ad/500] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/500] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #497: [GID:500@domain.ad] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #497: Looking up [GID:500@domain.ad] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a671e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a672b0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a671e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a672b0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a671e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a4e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a5b0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a4e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5b0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a4e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a628a0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a69f10
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a628a0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69f10 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a628a0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a69fd0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a627e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a69fd0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a627e0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a69fd0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [user@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #497: Returning [GID:500@domain.ad] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #497: Filtering out results by negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/domain.ad/tester@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #497: Found 1 entries in domain domain.ad (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #497: Finished: Success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.ad/user@domain.ad] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:37 2019) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 1095200010 (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #498: Setting "Group by ID" plugin (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #498: New request 'Group by ID' (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #498: Performing a multi-domain search (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #498: Search will check the cache and check the data provider (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/DOM_LOCATE_TYPE/domain.test/Group by ID] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.test type POSIX is valid (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #498: Using domain [domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #498: Looking up GID:1095200010@domain.test (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #498: Checking negative cache for [GID:1095200010@domain.test] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/domain.test/1095200010] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/1095200010] (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #498: [GID:1095200010@domain.test] is not present in negative cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #498: Looking up [GID:1095200010@domain.test] in cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a671e0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a672b0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a671e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a672b0 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a671e0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a5a0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a6a670
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a5a0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a670 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a5a0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a6a670
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a60490
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a6a670 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a60490 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a6a670 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a620f0
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a67e60
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a620f0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67e60 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a620f0 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x556496a5ed70
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x556496a67790
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Running timer event 0x556496a5ed70 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a67790 "ltdb_timeout"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x556496a5ed70 "ltdb_callback"
(Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [user@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [one@domain.ad] to [overridememberUid]. (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #498: Returning [GID:1095200010@domain.test] from cache (Mon Oct 28 16:43:37 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #498: Filtering out results by negative cache (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/domain.test/ad_groups@domain.test] (Mon Oct 28 16:43:38 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #498: Found 1 entries in domain domain.test (Mon Oct 28 16:43:38 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #498: Finished: Success (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.test/user@domain.ad] (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/domain.test/one@domain.ad] (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.test is Active (Mon Oct 28 16:43:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain domain.ad is Active (Mon Oct 28 16:43:38 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success (Mon Oct 28 16:43:46 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a642f0][21] (Mon Oct 28 16:43:46 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a55990][22] (Mon Oct 28 16:43:46 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a626b0][23] (Mon Oct 28 16:43:57 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x556496a64ec0][24]
Regards, Dani
On Mon, Oct 28, 2019 at 03:56:56PM -0000, Danijel Bojic via FreeIPA-users wrote:
Hi Alexander
Thanks for clarifying.
I don't see anything in the sssd_domain.log I see something though in the sssd_nss.log file. I crosschecked my sssd.conf file and corrected some spelling error and it seems to work now. I can su and ssh with the AD Domain users on the ipa client. Only thing now is that when i try to login in the gui, it just restarts the gui.
Hi,
please send the part of /var/log/secure (or the journalctl output) covering the time you try to log in with gdm.
Maybe you have an idea what to look into with this issue. Here's the output of nss.log:
I didn't see anything suspicious here.
bye, Sumit
Hi Sumit,
Here the log:
Oct 31 10:31:51 ipa-client sshd[39026]: pam_unix(sshd:session): session opened for user root by (uid=0) Oct 31 10:32:01 ipa-client lightdm: pam_sss(lightdm:auth): authentication success; logname= uid=0 euid=0 tty=:0 ruser= rhost= user=dabo@dectris.ad Oct 31 10:32:01 ipa-client lightdm: pam_unix(lightdm-greeter:session): session closed for user lightdm Oct 31 10:32:01 ipa-client lightdm: pam_unix(lightdm:session): session opened for user dabo@dectris.ad by (uid=0) Oct 31 10:32:01 ipa-client lightdm: pam_unix(lightdm:session): session closed for user dabo@dectris.ad Oct 31 10:32:01 ipa-client lightdm: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0) Oct 31 10:32:29 ipa-client lightdm: pam_sss(lightdm:auth): authentication success; logname= uid=0 euid=0 tty=:0 ruser= rhost= user=dabo@dectris.ad Oct 31 10:32:29 ipa-client lightdm: pam_unix(lightdm-greeter:session): session closed for user lightdm Oct 31 10:32:29 ipa-client lightdm: pam_unix(lightdm:session): session opened for user dabo@dectris.ad by (uid=0) Oct 31 10:32:29 ipa-client lightdm: pam_unix(lightdm:session): session closed for user dabo@dectris.ad Oct 31 10:32:29 ipa-client lightdm: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
(output from tailf /var/log/secure)
To clarify what i exactly see on the GUI: I enter my credentials, click login, it loads for like 1-3secs and then it kicks me out of the Graph interface and restarts it, i see following output: [OK]Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [OK]Sterted Update UTMP about System Runlevel Changes.
Best, Dani
Here the lightdm.log aswell. [root@ipa-client ~]# tailf /var/log/lightdm/lightdm.log [+236440.19s] DEBUG: Session pid=39337: Logging to /var/log/lightdm/seat0-greeter.log [+236440.20s] DEBUG: Activating VT 1 [+236440.20s] DEBUG: Activating login1 session c4 [+236440.20s] DEBUG: Seat seat0 changes active session to c4 [+236440.20s] DEBUG: Session c4 is already active [+236440.28s] DEBUG: Greeter connected version=1.25.0 api=1 resettable=false [+236440.54s] DEBUG: Greeter start authentication [+236440.54s] DEBUG: Session pid=39360: Started with service 'lightdm', username '(null)' [+236440.54s] DEBUG: Session pid=39360: Got 1 message(s) from PAM [+236440.54s] DEBUG: Prompt greeter with 1 message(s) [+255435.94s] DEBUG: Greeter start authentication for user@domain.ad [+255435.94s] DEBUG: Session pid=39360: Sending SIGTERM [+255435.94s] DEBUG: Session pid=42280: Started with service 'lightdm', username 'user@domain.ad' [+255435.94s] DEBUG: Session pid=39360: Terminated with signal 15 [+255435.94s] DEBUG: Session: Failed during authentication [+255435.94s] DEBUG: Seat seat0: Session stopped [+255436.23s] DEBUG: Session pid=42280: Got 1 message(s) from PAM [+255436.23s] DEBUG: Prompt greeter with 1 message(s) [+255442.92s] DEBUG: Continue authentication [+255443.09s] DEBUG: Session pid=42280: Authentication complete with return value 0: Success [+255443.09s] DEBUG: Authenticate result for user user@domain.ad: Success [+255443.09s] DEBUG: User user@domain.ad authorized [+255443.09s] DEBUG: Greeter sets language en_US.utf8 [+255443.09s] DEBUG: Greeter requests session gnome [+255443.09s] DEBUG: Seat seat0: Stopping greeter; display server will be re-used for user session [+255443.09s] DEBUG: Terminating login1 session c4 [+255443.09s] DEBUG: Session pid=39337: Sending SIGTERM [+255443.10s] DEBUG: Greeter closed communication channel [+255443.10s] DEBUG: Session pid=39337: Exited with return value 1 [+255443.10s] DEBUG: Seat seat0: Session stopped [+255443.10s] DEBUG: Seat seat0: Greeter stopped, running session [+255443.10s] DEBUG: Registering session with bus path /org/freedesktop/DisplayManager/Session3 [+255443.10s] DEBUG: Session pid=42280: Running command /etc/X11/xinit/Xsession gnome-session [+255443.10s] DEBUG: Creating shared data directory /var/lib/lightdm-data/user@domain.ad [+255443.10s] WARNING: Could not chown user data directory /var/lib/lightdm-data/user@domain.ad: Error creating directory /var/lib/lightdm-data/user@domain.ad: File exists [+255443.10s] DEBUG: Session pid=42280: Logging to .xsession-errors [+255443.12s] DEBUG: Activating VT 1 [+255443.12s] DEBUG: Activating login1 session 505 [+255443.12s] DEBUG: Seat seat0 changes active session to 505 [+255443.12s] DEBUG: Session 505 is already active [+255443.30s] DEBUG: Session pid=42280: Exited with return value 1 [+255443.30s] DEBUG: Seat seat0: Session stopped [+255443.30s] DEBUG: Seat seat0: Stopping display server, no sessions require it [+255443.30s] DEBUG: Sending signal 15 to process 39329 [+255443.36s] DEBUG: Process 39329 exited with return value 0 [+255443.36s] DEBUG: XServer 0: X server stopped [+255443.36s] DEBUG: Releasing VT 1 [+255443.36s] DEBUG: XServer 0: Removing X server authority /var/run/lightdm/root/:0 [+255443.36s] DEBUG: Seat seat0: Display server stopped [+255443.36s] DEBUG: Seat seat0: Active display server stopped, starting greeter [+255443.36s] DEBUG: Seat seat0: Creating greeter session [+255443.36s] DEBUG: Seat seat0: Creating display server of type x [+255443.36s] DEBUG: Using VT 1 [+255443.36s] DEBUG: Seat seat0: Starting local X display on VT 1 [+255443.36s] DEBUG: XServer 0: Logging to /var/log/lightdm/x-0.log [+255443.36s] DEBUG: XServer 0: Writing X server authority to /var/run/lightdm/root/:0 [+255443.36s] DEBUG: XServer 0: Launching X Server [+255443.36s] DEBUG: Launching process 42327: /usr/bin/X -core -noreset :0 -seat seat0 -auth /var/run/lightdm/root/:0 -nolisten tcp vt1 -novtswitch -background none [+255443.36s] DEBUG: XServer 0: Waiting for ready signal from X server :0 [+255443.57s] DEBUG: Got signal 10 from process 42327 [+255443.57s] DEBUG: XServer 0: Got signal from X server :0 [+255443.57s] DEBUG: XServer 0: Connecting to XServer :0 [+255443.57s] DEBUG: Seat seat0: Display server ready, starting session authentication [+255443.57s] DEBUG: Session pid=42335: Started with service 'lightdm-greeter', username 'lightdm' [+255443.58s] DEBUG: Session pid=42335: Authentication complete with return value 0: Success [+255443.58s] DEBUG: Seat seat0: Session authenticated, running command [+255443.58s] DEBUG: Session pid=42335: Running command /usr/sbin/lightdm-gtk-greeter [+255443.58s] DEBUG: Creating shared data directory /var/lib/lightdm-data/lightdm [+255443.58s] WARNING: Could not chown user data directory /var/lib/lightdm-data/lightdm: Error creating directory /var/lib/lightdm-data/lightdm: File exists [+255443.58s] DEBUG: Session pid=42335: Logging to /var/log/lightdm/seat0-greeter.log [+255443.59s] DEBUG: Activating VT 1 [+255443.59s] DEBUG: Activating login1 session c5 [+255443.60s] DEBUG: Seat seat0 changes active session to c5 [+255443.60s] DEBUG: Session c5 is already active [+255443.66s] DEBUG: Greeter connected version=1.25.0 api=1 resettable=false [+255443.89s] DEBUG: Greeter start authentication [+255443.89s] DEBUG: Session pid=42358: Started with service 'lightdm', username '(null)' [+255443.90s] DEBUG: Session pid=42358: Got 1 message(s) from PAM [+255443.90s] DEBUG: Prompt greeter with 1 message(s)
freeipa-users@lists.fedorahosted.org
-
Alexander Bokovoy -
Danijel Bojic -
Jones, Bob (rwj5d) -
Sumit Bose