freeipa

#8162 su to AD user failed after AD cross-forest trusts setup
Closed: invalid by abbra. Opened by diadormu.

Closed: invalid
Reopen Issue

I follow the documentation https://www.freeipa.org/page/Active_Directory_trust_setup deploy AD cross-forest trusts setup (IPA is subdomain of AD, AD administrator credentials aren't available) succeed (i think). I having two problems and a suggestion.

The first problem

su to an AD user failed:

[centos@freeipa ~]$ su - scm@scmtest.com
Password: 
su: Authentication failure

and the error log in /var/log/secure:

Jan  3 11:58:12 freeipa su: pam_sss(su-l:auth): authentication failure; logname=centos uid=1000 euid=0 tty=pts/0 ruser=centos rhost= user=scm@scmtest.com
Jan  3 11:58:12 freeipa su: pam_sss(su-l:auth): received for user scm@scmtest.com: 6 (Permission denied)

But

sudo su - scm@scmtest.com

and

kinit scm@scmtest.com

succeed.
Is it any problems at the AD user or sssd's configition?
My freeipa server and client version is 4.6.5-11 , system is CentOS Linux release 7.7.1908, AD system is Windows Server 2012 R2.
krb5_child.log and sssd_rnd.scmtest.com.log added at last.

The second problem

Could authenticate AD users in other applications (e.g. Jenkins, GIt) through IPA? Or import AD users and groups into IPA's ldap?
Because I haven't AD's permissions, but I need to manage these users. When the first problem is solved, I'll face this problem. If can't, I need to create those users and groups by myself.

A suggestion

I suggest to add a Note at https://www.freeipa.org/page/Active_Directory_trust_setup#When_AD_administrator_credentials_aren.27t_available about the gif:
When enter the Trust Name at New Trust Wizard, the Name is ipa_domain
On my first try, I entered full ipa_hostname, then all were different from the gif :-(

Last, the log files

ad_ip_address: 172.16.14.94
ad_hostname: sh-2012r2-94-0
ad_domain: scmtest.com
ad_netbios: SCMTEST
ipa_ip_address: 172.16.17.134
ipa_hostname: freeipa.rnd.scmtest.com
ipa_domain: rnd.scmtest.com
ipa_netbios: RND

krb5_child.log

(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [main] (0x0400): krb5_child started.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [unpack_buffer] (0x1000): total buffer size: [145]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [unpack_buffer] (0x0100): cmd [249] uid [1218801105] gid [1218801105] validate [true] enterprise principal [false] offline [false] UPN [scm@SCMTEST.COM]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1218801105] old_ccname: [KEYRING:persistent:1218801105] keytab: [/etc/krb5.keytab]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM in keytab.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [match_principal] (0x1000): Principal matched to the sample (host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM).
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [become_user] (0x0200): Trying to become user [1218801105][1218801105].
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [main] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [k5c_setup] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [main] (0x0400): Will perform pre-auth
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SCMTEST.COM]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494866: Getting initial credentials for scm@SCMTEST.COM
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494867: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_RND.SCMTEST.COM
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494868: Retrieving host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/SCMTEST.COM\@SCMTEST.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_RND.SCMTEST.COM with result: -1765328243/Matching credential not found
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494870: Sending unauthenticated request
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494871: Sending request (169 bytes) to SCMTEST.COM
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494872: Initiating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494873: Sending TCP request to stream 172.16.14.94:88
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494874: Received answer (180 bytes) from stream 172.16.14.94:88
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494875: Terminating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494876: Response was from master KDC
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494877: Received error from KDC: -1765328359/Additional pre-authentication required
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494880: Preauthenticating using KDC method data
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494881: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2)
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494882: Selected etype info: etype aes256-cts, salt "SCMTEST.COMscm", params ""
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494883: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_krb5_responder] (0x4000): Got question [password].
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494884: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494885: Preauth module pkinit (16) (real) returned: 22/Invalid argument
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494886: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494887: Preauth module pkinit (14) (real) returned: 22/Invalid argument
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for scm@SCMTEST.COM].
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [sss_child_krb5_trace_cb] (0x4000): [12513] 1578023886.494888: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [k5c_send_data] (0x0200): Received error code 0
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [pack_response_packet] (0x2000): response packet size: [12]
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Jan  3 11:58:06 2020) [[sssd[krb5_child[12513]]]] [main] (0x0400): krb5_child completed successfully
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [main] (0x0400): krb5_child started.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [unpack_buffer] (0x1000): total buffer size: [155]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [unpack_buffer] (0x0100): cmd [241] uid [1218801105] gid [1218801105] validate [true] enterprise principal [false] offline [false] UPN [scm@SCMTEST.COM]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1218801105] old_ccname: [KEYRING:persistent:1218801105] keytab: [/etc/krb5.keytab]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [switch_creds] (0x0200): Switch user to [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [switch_creds] (0x0200): Switch user to [0][0].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1218801105] and is not active and TGT is  valid.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM in keytab.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [match_principal] (0x1000): Principal matched to the sample (host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM).
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [become_user] (0x0200): Trying to become user [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [main] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_setup] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [main] (0x0400): Will perform online auth
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SCMTEST.COM]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158547: Getting initial credentials for scm@SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158548: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_RND.SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158549: Retrieving host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/SCMTEST.COM\@SCMTEST.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_RND.SCMTEST.COM with result: -1765328243/Matching credential not found
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158551: Sending unauthenticated request
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158552: Sending request (169 bytes) to SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158553: Initiating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158554: Sending TCP request to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158555: Received answer (179 bytes) from stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158556: Terminating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158557: Response was from master KDC
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158558: Received error from KDC: -1765328359/Additional pre-authentication required
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158561: Preauthenticating using KDC method data
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158562: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2)
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158563: Selected etype info: etype aes256-cts, salt "SCMTEST.COMscm", params ""
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158564: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_krb5_responder] (0x4000): Got question [password].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158565: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158566: Preauth module pkinit (16) (real) returned: 22/Invalid argument
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158567: PKINIT client has no configured identity; giving up
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158568: Preauth module pkinit (14) (real) returned: 22/Invalid argument
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158569: AS key obtained for encrypted timestamp: aes256-cts/97FE
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158571: Encrypted timestamp (for 1578024230.32112): plain 3019A011180F32303230303130333034303335305AA10402027D70, encrypted BE6603668028E3C204ACF782C0DB8A5485C6964FBA7EDCB51AB1CF5907559B7221BD889036E87F70BDDA25997DE6FDD169893DBA4163BA
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158572: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158573: Produced preauth for next request: PA-ENC-TIMESTAMP (2)
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158574: Sending request (246 bytes) to SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158575: Initiating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158576: Sending TCP request to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158577: Received answer (1469 bytes) from stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158578: Terminating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158579: Response was from master KDC
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158580: Processing preauth types: PA-ETYPE-INFO2 (19)
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158581: Selected etype info: etype aes256-cts, salt "SCMTEST.COMscm", params ""
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158582: Produced preauth for next request: (empty)
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158583: AS key determined by preauth: aes256-cts/97FE
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158584: Decrypted AS reply; session key is: aes256-cts/2904
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158585: FAST negotiation: unavailable
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [558485393]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [validate_tgt] (0x2000): Keytab entry with the realm of the credential not found in keytab. Using the last entry.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158586: Retrieving host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158587: Resolving unique ccache of type MEMORY
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158588: Initializing MEMORY:6bI4Ke4 with default princ scm@SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158589: Storing scm@SCMTEST.COM -> krbtgt/SCMTEST.COM@SCMTEST.COM in MEMORY:6bI4Ke4
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158590: Getting credentials scm@SCMTEST.COM -> host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM using ccache MEMORY:6bI4Ke4
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158591: Retrieving scm@SCMTEST.COM -> host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM from MEMORY:6bI4Ke4 with result: -1765328243/Matching credential not found
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158592: Retrieving scm@SCMTEST.COM -> krbtgt/RND.SCMTEST.COM@RND.SCMTEST.COM from MEMORY:6bI4Ke4 with result: -1765328243/Matching credential not found
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158593: Retrieving scm@SCMTEST.COM -> krbtgt/SCMTEST.COM@SCMTEST.COM from MEMORY:6bI4Ke4 with result: 0/Success
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158594: Starting with TGT for client realm: scm@SCMTEST.COM -> krbtgt/SCMTEST.COM@SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158595: Retrieving scm@SCMTEST.COM -> krbtgt/RND.SCMTEST.COM@RND.SCMTEST.COM from MEMORY:6bI4Ke4 with result: -1765328243/Matching credential not found
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158596: Requesting TGT krbtgt/RND.SCMTEST.COM@SCMTEST.COM using TGT krbtgt/SCMTEST.COM@SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158597: Generated subkey for TGS request: aes256-cts/7A79
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158598: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158600: Encoding request body and padata into FAST request
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158601: Sending request (1627 bytes) to SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158602: Initiating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158603: Sending TCP request to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158604: Received answer (1537 bytes) from stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158605: Terminating TCP connection to stream 172.16.14.94:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158606: Response was from master KDC
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158607: Decoding FAST response
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158608: FAST reply key: aes256-cts/23E1
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158609: TGS reply is for scm@SCMTEST.COM -> krbtgt/RND.SCMTEST.COM@SCMTEST.COM with session key rc4-hmac/833E
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158610: TGS request result: 0/Success
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158611: Storing scm@SCMTEST.COM -> krbtgt/RND.SCMTEST.COM@SCMTEST.COM in MEMORY:6bI4Ke4
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158612: Received TGT for service realm: krbtgt/RND.SCMTEST.COM@SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158613: Requesting tickets for host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM, referrals on
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158614: Generated subkey for TGS request: rc4-hmac/57AA
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158615: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158617: Encoding request body and padata into FAST request
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158618: Sending request (1619 bytes) to RND.SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158619: Initiating TCP connection to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158620: Sending TCP request to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158621: Received answer (177 bytes) from stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158622: Terminating TCP connection to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158623: Response was from master KDC
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158624: TGS request result: -1765328351/Ticket not yet valid
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158625: Requesting tickets for host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM, referrals off
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158626: Generated subkey for TGS request: rc4-hmac/1F67
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158627: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158629: Encoding request body and padata into FAST request
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158630: Sending request (1619 bytes) to RND.SCMTEST.COM
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158631: Initiating TCP connection to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158632: Sending TCP request to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158633: Received answer (177 bytes) from stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158634: Terminating TCP connection to stream 172.16.17.134:88
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158635: Response was from master KDC
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158636: TGS request result: -1765328351/Ticket not yet valid
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [sss_child_krb5_trace_cb] (0x4000): [12515] 1578023892.158637: Destroying ccache MEMORY:6bI4Ke4
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [validate_tgt] (0x0020): TGT failed verification using key for [host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [get_and_save_tgt] (0x0020): 1741: [-1765328351][Ticket not yet valid]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [map_krb5_error] (0x0020): 1817: [-1765328351][Ticket not yet valid]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_send_data] (0x0200): Received error code 1432158229
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [pack_response_packet] (0x2000): response packet size: [20]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [main] (0x0400): krb5_child completed successfully
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [main] (0x0400): krb5_child started.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [unpack_buffer] (0x1000): total buffer size: [155]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [unpack_buffer] (0x0100): cmd [241] uid [1218801105] gid [1218801105] validate [true] enterprise principal [false] offline [true] UPN [scm@SCMTEST.COM]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1218801105] old_ccname: [KEYRING:persistent:1218801105] keytab: [/etc/krb5.keytab]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [switch_creds] (0x0200): Switch user to [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [switch_creds] (0x0200): Switch user to [0][0].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1218801105] and is not active and TGT is  valid.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [become_user] (0x0200): Trying to become user [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [main] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [become_user] (0x0200): Trying to become user [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [become_user] (0x0200): Already user [1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [k5c_setup] (0x2000): Running as [1218801105][1218801105].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [main] (0x0400): Will perform offline auth
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [create_empty_ccache] (0x1000): Existing ccache still valid, reusing
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [k5c_send_data] (0x0200): Received error code 0
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [pack_response_packet] (0x2000): response packet size: [53]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12516]]]] [main] (0x0400): krb5_child completed successfully

sssd_rnd.scmtest.com.log

(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da270e50
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0a70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d0fd0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0a70 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0a70 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d2520
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bcc00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d2520 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bcc00 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d2520 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2bc3c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e31a0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2bc3c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ce120
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2ce1f0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e31a0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc3c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ce120 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ce1f0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ce120 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #81]: New request. Flags [0x0001].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaUserOverride)(uid=scm))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=scm))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 24
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 24 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 24 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaUserOverride)(uid=scm))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0fd0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d0a70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0a70 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0fd0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bc3c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc3c0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da28cb20
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d0a70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da28cb20 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0a70 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28cb20 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [check_if_pac_is_available] (0x4000): No PAC available.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [get_ldap_conn_from_sdom_pvt] (0x4000): Returning LDAP connection for user lookup.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=scmtest,dc=com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.14.94:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=scm)(objectclass=user)(objectSID=*))][dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 8
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 8 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[(nil)], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2e5840], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [accountExpires]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2e5840], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.scmtest.com/DC=ForestDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2e5840], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.scmtest.com/DC=DomainDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2e5840], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://scmtest.com/CN=Configuration,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2e5840], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 8 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://ForestDnsZones.scmtest.com/DC=ForestDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://DomainDnsZones.scmtest.com/DC=DomainDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://scmtest.com/CN=Configuration,DC=scmtest,DC=com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Storing the user
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Save user
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_primary_name] (0x0400): Processing object scm
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Processing user scm@scmtest.com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x1000): Mapping user [scm@scmtest.com] objectSID [S-1-5-21-3964881776-3541446604-2987880693-1105] to unix ID
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=scm,CN=Users,DC=scmtest,DC=com] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Original memberOf is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20191231103629.0Z] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Adding user principal [scm@SCMTEST.COM] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adAccountExpires [9223372036854775807] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [66048] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedRHost is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): mail is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Storing info for user scm@scmtest.com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2b3680
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3e60
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e60 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e41a0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e4270
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e41a0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4270 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2b1230
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e41a0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2b1230 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b1230 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e38c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2b1170
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b1170 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2cff90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29c120
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2cff90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29c120 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2cff90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29b790
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29c080
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29b790 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29c080 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b790 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3ca0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3d70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3ca0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3d70 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3ca0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29cab0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3800
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29cab0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3800 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29cab0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [originalMemberOf] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29b6d0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d4ae0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29b6d0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d4ae0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b6d0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userCertificate] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2be930
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d1590
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2be930 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1590 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2be930 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [mail] from [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2be930
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29af80
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2be930 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29af80 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2be930 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Commit change
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e4260
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da292f40
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e4260 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292f40 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4260 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2cd500
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e41a0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2cd500 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2cd500 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Process user's groups
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.14.94:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 9 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [tokenGroups]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 9 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-545]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-545][BUILTIN\Users] which is currently not handled by SSSD.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-3964881776-3541446604-2987880693-513]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2be9f0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2758d0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2be9f0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2758d0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2be9f0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e38c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2be930
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2be930 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29a280
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da28caa0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29a280 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28caa0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a280 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29b180
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29a280
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29b180 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a280 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b180 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e5310
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3e90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e5310 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e5310 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [scm@scmtest.com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x4000): Initgroups done
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x1000): Mapping primary group to unix ID
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e38c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29a280
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a280 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e38c0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e4430
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29b180
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e4430 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b180 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4430 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x0400): Primary group already cached, nothing to do.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x4000): No need to check for domain local group memberships.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e4840
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29cab0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e4840 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29cab0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4840 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3e90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e5310
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e5310 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ccf00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3e90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ccf00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccf00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [apply_subdomain_homedir] (0x4000): Missing homedir of scm@scmtest.com.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ccf00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e4c00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ccf00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4c00 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccf00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_ldb_msg_difference] (0x2000): Added attr [homeDirectory] to entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3e90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c02d0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c02d0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [cache, ts_cache] attrs.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 25
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 25 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[(nil)], ldap[0x5635da279a60]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 25 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ccdd0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bff00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ccdd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3120
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e31f0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bff00 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccdd0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3120 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e31f0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3120 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 0/1
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Fetching group S-1-5-21-3964881776-3541446604-2987880693-513
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 26
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 26 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e1660], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e1660], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 26 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 1/1
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_search_bases_ex_next_base] (0x0400): Issuing LDAP lookup with base [cn=accounts,dc=rnd,dc=scmtest,dc=com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [objectClass=ipaexternalgroup][cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 27
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 27 timeout 60
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ad_admins_external,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [description]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaExternalMember]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ad_users,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaExternalMember]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ad_scm,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaExternalMember]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e3610], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 27 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_search_bases_ex_done] (0x0400): Receiving data from base [cn=accounts,dc=rnd,dc=scmtest,dc=com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ext_groups_done] (0x0400): [3] external groups found.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding SID [S-1-5-21-3964881776-3541446604-2987880693-512] to external group hash.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding group [cn=ad_admins,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] to SID [S-1-5-21-3964881776-3541446604-2987880693-512].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding SID [S-1-5-21-3964881776-3541446604-2987880693-513] to external group hash.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] to SID [S-1-5-21-3964881776-3541446604-2987880693-513].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding SID [S-1-5-21-3964881776-3541446604-2987880693-1105] to external group hash.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [process_ext_groups] (0x4000): Adding group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] to SID [S-1-5-21-3964881776-3541446604-2987880693-1105].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d1f00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3aa0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d1f00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3aa0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1f00 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d1d90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d1e60
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d1d90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1e60 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1d90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d1e30
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29ae70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d1e30 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d55d0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d56a0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29ae70 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1e30 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d55d0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d56a0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d55d0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(originalDN=cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com))
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d57e0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29aee0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d57e0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29aee0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d57e0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): No such entry
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [add_ad_user_to_cached_groups] (0x4000): Group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] not in the cache.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=accounts,dc=rnd,dc=scmtest,dc=com]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipausers)(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [posixGroup]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTSecurityIdentifier]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaExternalMember]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 28
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 28 timeout 6
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2d0700], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2d0700], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 28 finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(originalDN=cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com))
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3be0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3cb0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3be0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3cb0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3be0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): No such entry
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [add_ad_user_to_cached_groups] (0x4000): Group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] not in the cache.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_add_ad_memberships_get_next] (0x0020): There are unresolved external group memberships even after all groups have been looked up on the LDAP server.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #81]: Request handler finished [0]: Success
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #81]: Receiving request data.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c1ff0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2ccf00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c1ff0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccf00 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c1ff0 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da28cc50
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bea40
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da28cc50
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bc3c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc3c0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3e90
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2ccf00
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccf00 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #81]: Finished. Success.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #81]: Returning [Success]: 0,0,Success
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::scmtest.com:name=scm@scmtest.com] from reply table
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #81]: Request removed.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[(nil)], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da2571b0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da270e50
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_pam_handler] (0x0100): Got request with the following data
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): domain: scmtest.com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): user: scm@scmtest.com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): service: su-l
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): tty: pts/0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): ruser: centos
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): rhost: 
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): priv: 0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): cli_pid: 12509
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): logon name: not set
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #82]: New request. Flags [0000].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [scm@scmtest.com] is empty, running request [0x5635da29df70] immediately.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [krb5_setup] (0x4000): No mapping for: scm@scmtest.com
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da294500
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d0a70
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da294500 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0a70 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29a450
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bc0e0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc0e0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [be_resolve_server_process] (0x0200): Found address for server freeipa.rnd.scmtest.com: [172.16.17.134] TTL 7200
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://freeipa.rnd.scmtest.com'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [krb5_add_krb5info_offline_callback] (0x4000): Removal callback already available for service [IPA].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_dJEqsQ]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_dJEqsQ]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [12513]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [12513]
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x1000): Waiting for child [12513].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x0100): child [12513] finished successfully.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [parse_krb5_child_response] (0x1000): child response [0][11][0].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1089
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [set_server_common_status] (0x0100): Marking server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:1218801105] for user [scm@scmtest.com].
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da279990
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c16c0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da279990 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c16c0 "ltdb_timeout"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da279990 "ltdb_callback"
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [check_wait_queue] (0x1000): Wait queue for user [scm@scmtest.com] is empty.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x5635da29df70] done.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #82]: Request handler finished [0]: Success
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #82]: Receiving request data.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #82]: Request removed.
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Fri Jan  3 11:58:06 2020) [sssd[be[rnd.scmtest.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Preauth #82]: Sending result [0][scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da270e50
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0a70
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da294500
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0a70 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0a70 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da28cc50
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da294500
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29c2a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29ca40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29c2a0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e36d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e37a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29ca40 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29c2a0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e36d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e37a0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e36d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #83]: New request. Flags [0x0001].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaUserOverride)(uid=scm))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=scm))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 29
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 29 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da276e40], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 29 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaUserOverride)(uid=scm))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3450
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d2520
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d2520 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da292310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29a450
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a450 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da292310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292310 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [check_if_pac_is_available] (0x4000): No PAC available.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_ldap_conn_from_sdom_pvt] (0x4000): Returning LDAP connection for user lookup.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=scmtest,dc=com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.14.94:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=scm)(objectclass=user)(objectSID=*))][dc=scmtest,dc=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 10
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 10 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[(nil)], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2c16c0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [accountExpires]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2c16c0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.scmtest.com/DC=ForestDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2c16c0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.scmtest.com/DC=DomainDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2c16c0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://scmtest.com/CN=Configuration,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2c16c0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 10 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://ForestDnsZones.scmtest.com/DC=ForestDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://DomainDnsZones.scmtest.com/DC=DomainDnsZones,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://scmtest.com/CN=Configuration,DC=scmtest,DC=com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Storing the user
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Save user
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_primary_name] (0x0400): Processing object scm
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Processing user scm@scmtest.com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x1000): Mapping user [scm@scmtest.com] objectSID [S-1-5-21-3964881776-3541446604-2987880693-1105] to unix ID
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=scm,CN=Users,DC=scmtest,DC=com] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Original memberOf is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20191231103629.0Z] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Adding user principal [scm@SCMTEST.COM] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adAccountExpires [9223372036854775807] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [66048] to attributes of [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedRHost is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_attrs_add_ldap_attr] (0x2000): mail is not available for [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_save_user] (0x0400): Storing info for user scm@scmtest.com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c0ea0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c1e00
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c0ea0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c1e00 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c0ea0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c4200
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c42d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c4200 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c42d0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c4200 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29c2f0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29b3b0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29c2f0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b3b0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29c2f0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2b3680
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29b3b0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b3b0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d1310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29b180
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d1310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29b180 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c4200
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c42d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c4200 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c42d0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c4200 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3e00
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29c230
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3e00 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29c230 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e00 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29afd0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2b35c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29afd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b35c0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29afd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [originalMemberOf] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3d40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3e10
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3d40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e10 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3d40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userCertificate] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3e00
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2b8630
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3e00 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b8630 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e00 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [mail] from [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3d40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3e10
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3d40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e10 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3d40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Commit change
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ccb20
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2ccbf0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ccb20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccbf0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccb20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e3d30
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3e00
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e3d30 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3e00 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3d30 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_user] (0x4000): Process user's groups
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.14.94:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 11
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 11 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=scm,CN=Users,DC=scmtest,DC=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [tokenGroups]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[0x5635da2d4ba0], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 11 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-545]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x0400): Skipping SID [S-1-5-32-545][BUILTIN\Users] which is currently not handled by SSSD.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-3964881776-3541446604-2987880693-513]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e5480
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e5550
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e5480 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e5550 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e5480 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e5540
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e41a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e5540 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e5540 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c0e20
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c0ef0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c0e20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c0ef0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c0e20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c0e20
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c0ef0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c0e20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c0ef0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c0e20 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0630
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e41a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0630 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0630 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [scm@scmtest.com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x4000): Initgroups done
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x1000): Mapping primary group to unix ID
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2b3680
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da28f860
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28f860 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b3680 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d1820
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d18f0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d1820 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d18f0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d1820 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x0400): Primary group already cached, nothing to do.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_initgr_done] (0x4000): No need to check for domain local group memberships.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2942c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2b3630
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2942c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2b3630 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2942c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d2520
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bc070
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d2520 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc070 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d2520 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0fd0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e4240
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4240 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [apply_subdomain_homedir] (0x4000): Missing homedir of scm@scmtest.com.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0fd0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d2520
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d2520 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_ldb_msg_difference] (0x2000): Added attr [homeDirectory] to entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d0fd0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d0fd0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [cache, ts_cache] attrs.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 30
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 30 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da2b1ef0], connected[1], ops[(nil)], ldap[0x5635da279a60]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2c16c0], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 30 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-1105))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2942c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da279990
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2942c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c1eb0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c1f80
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da279990 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2942c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c1eb0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c1f80 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c1eb0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 0/1
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Fetching group S-1-5-21-3964881776-3541446604-2987880693-513
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))][cn=Default Trust View,cn=views,cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 31
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 31 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e1660], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2e1660], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 31 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3964881776-3541446604-2987880693-513))].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 1/1
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_get_ad_memberships_send] (0x0400): External group information still valid.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da292310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292310 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e4240
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e4240 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4240 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2ccc40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a36a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2ccc40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2d5420
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d54f0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a36a0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccc40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2d5420 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d54f0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d5420 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(originalDN=cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com))
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da292310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da278a80
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da278a80 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): No such entry
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [add_ad_user_to_cached_groups] (0x4000): Group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] not in the cache.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=accounts,dc=rnd,dc=scmtest,dc=com]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_print_server] (0x2000): Searching 172.16.17.134:389
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipausers)(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=rnd,dc=scmtest,dc=com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [posixGroup]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTSecurityIdentifier]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaExternalMember]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 32
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_add] (0x2000): New operation 32 timeout 6
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2c16c0], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[0x5635da2c16c0], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_op_destructor] (0x2000): Operation 32 finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(originalDN=cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com))
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da278a80
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da29a280
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da278a80 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a280 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da278a80 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_search_groups] (0x2000): No such entry
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [add_ad_user_to_cached_groups] (0x4000): Group [cn=ipausers,cn=groups,cn=accounts,dc=rnd,dc=scmtest,dc=com] not in the cache.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_add_ad_memberships_get_next] (0x0020): There are unresolved external group memberships even after all groups have been looked up on the LDAP server.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #83]: Request handler finished [0]: Success
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #83]: Receiving request data.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da292310
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da292310 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da294500
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2ccdd0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da294500 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2ccdd0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2c02d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c02d0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da28cc50
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2d8540
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2d8540 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28cc50 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #83]: Finished. Success.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #83]: Returning [Success]: 0,0,Success
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::scmtest.com:name=scm@scmtest.com] from reply table
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #83]: Request removed.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: sh[0x5635da29e490], connected[1], ops[(nil)], ldap[0x5635da2945c0]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da2571b0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x5635da270e50
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_pam_handler] (0x0100): Got request with the following data
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): domain: scmtest.com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): user: scm@scmtest.com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): service: su-l
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): tty: pts/0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): ruser: centos
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): rhost: 
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): authtok type: 1
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): priv: 0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): cli_pid: 12509
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [pam_print_data] (0x0100): logon name: not set
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #84]: New request. Flags [0000].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [scm@scmtest.com] is empty, running request [0x5635da2d1cf0] immediately.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain rnd.scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_setup] (0x4000): No mapping for: scm@scmtest.com
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c02d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da294500
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c02d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c02d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c02d0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bea40
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c02d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bea40 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c02d0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [be_resolve_server_process] (0x0200): Found address for server freeipa.rnd.scmtest.com: [172.16.17.134] TTL 7200
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://freeipa.rnd.scmtest.com'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_add_krb5info_offline_callback] (0x4000): Removal callback already available for service [IPA].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_cBKvKw]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_cBKvKw]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sss_domain_get_state] (0x1000): Domain scmtest.com is Active
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [12515]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [12515]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x1000): Waiting for child [12515].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x0100): child [12515] finished successfully.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [parse_krb5_child_response] (0x1000): child response [1432158229][6][8].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_NOT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 982
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'freeipa.rnd.scmtest.com' as 'not working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'freeipa.rnd.scmtest.com' as 'not working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'freeipa.rnd.scmtest.com' is 'not working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_server_status] (0x1000): Status of server 'freeipa.rnd.scmtest.com' is 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'freeipa.rnd.scmtest.com' is 'not working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_resolve_service_send] (0x0020): No available servers for service 'IPA'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [be_mark_dom_offline] (0x1000): Marking subdomain scmtest.com offline
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2bc3c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e3450
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2bc3c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e3450 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc3c0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [be_mark_subdom_offline] (0x1000): Marking subdomain scmtest.com as inactive
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [12516]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [12516]
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x1000): Waiting for child [12516].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [child_sig_handler] (0x0100): child [12516] finished successfully.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [parse_krb5_child_response] (0x1000): child response [0][3][41].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1089
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [set_server_common_status] (0x0100): Marking server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'freeipa.rnd.scmtest.com' as 'working'
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:1218801105] for user [scm@scmtest.com].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da293110
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e38c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da293110 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e38c0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da293110 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=scm@scmtest.com,cn=users,cn=scmtest.com,cn=sysdb] has set [ts_cache] attrs.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2c1a10
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da28caa0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2c1a10 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da28caa0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2c1a10 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29a450
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2bc3c0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2bc3c0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da29a450
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da294500
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da294500 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da29a450 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e41a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2a3e90
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e41a0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_auth] (0x4000): Offline credentials expiration is [0] days.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2e4630
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e41a0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2e4630 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e41a0 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4630 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x5635da2a3e90
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x5635da2e4630
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Running timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2e4630 "ltdb_timeout"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): Destroying timer event 0x5635da2a3e90 "ltdb_callback"
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [check_failed_login_attempts] (0x4000): Failed login attempts [0], allowed failed login attempts [0], failed login delay [5].
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [sysdb_cache_auth] (0x0100): Cached credentials not available.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0)
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [check_wait_queue] (0x1000): Wait queue for user [scm@scmtest.com] is empty.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x5635da2d1cf0] done.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #84]: Request handler finished [0]: Success
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #84]: Receiving request data.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #84]: Request removed.
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Fri Jan  3 11:58:12 2020) [sssd[be[rnd.scmtest.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #84]: Sending result [6][scmtest.com]

Hi,

in krb5_child.log there is:

(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [validate_tgt] (0x0020): TGT failed verification using key for [host/freeipa.rnd.scmtest.com@RND.SCMTEST.COM].
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [get_and_save_tgt] (0x0020): 1741: [-1765328351][Ticket not yet valid]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [map_krb5_error] (0x0020): 1817: [-1765328351][Ticket not yet valid]
(Fri Jan  3 11:58:12 2020) [[sssd[krb5_child[12515]]]] [k5c_send_data] (0x0200): Received error code 1432158229

Please check the date and time on all involved IPA servers and AD DCs.

HTH

bye,
Sumit

Please get your time in sync across AD and IPA.

Metadata Update from @abbra:
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)

It works on the server, but there are further issues on Ubuntu (16.04 LTS) client.

ubuntu@sh-13-56:~$ kinit scm@scmtest.com
kinit: Cannot find KDC for realm "scmtest.com" while getting initial credentials

then i installed krb5-admin-server (1.13.2+dfsg-5ubuntu2.1) and linked /etc/krb5.conf to /etc/krb5/kdc.conf

lrwxrwxrwx 1 root root 14 1月 7 19:07 /etc/krb5kdc/kdc.conf -> /etc/krb5.conf

but started krb5-kdc server failed

1月 08 14:57:30 sh-13-56.rnd.scmtest.com krb5kdc[4382]: krb5kdc: cannot initialize realm RND.SCMTEST.COM - see log file for details

krb5kdc.log

krb5kdc: No such file or directory - while initializing database for realm RND.SCMTEST.COM
krb5kdc: No such file or directory - while initializing database for realm RND.SCMTEST.COM

Ubuntu's ipa client is 4.3.1-0ubuntu1

/etc/krb5.conf ,it cleated by ipa client i only add auth_to_local (from AD cross-forest trusts setup documentation) and logging (copy from server's krb5.conf)

#File modified by ipa-client-install
includedir /var/lib/sss/pubconf/krb5.include.d/
[libdefaults]
  default_realm = RND.SCMTEST.COM
  dns_lookup_realm = false
  dns_lookup_kdc = false
  rdns = false
  ticket_lifetime = 24h
  forwardable = true
  udp_preference_limit = 0
  default_ccache_name = KEYRING:persistent:%{uid}
[realms]
  RND.SCMTEST.COM = {
    kdc = freeipa.rnd.scmtest.com:88
    master_kdc = freeipa.rnd.scmtest.com:88
    admin_server = freeipa.rnd.scmtest.com:749
    default_domain = rnd.scmtest.com
    pkinit_anchors = FILE:/etc/ipa/ca.crt
    auth_to_local = RULE:[1:$1@$0](^.*@scmtest.com$)s/@scmtest.com/@scmtest.com/
    auth_to_local = DEFAULT
  }
[domain_realm]
  .rnd.scmtest.com = RND.SCMTEST.COM
  rnd.scmtest.com = RND.SCMTEST.COM
[logging]
 default = FILE:/var/log/krb5libs.log
 kdc = FILE:/var/log/krb5kdc.log
 admin_server = FILE:/var/log/kadmind.log
Edited by diadormu

Metadata Update from @diadormu:
- Issue status updated to: Open (was: Closed)

You have no definition for realm(s) representing AD domain(s) and you have

 dns_lookup_realm = false
 dns_lookup_kdc = false

this means Kerberos library couldn't know about those realms and cannot search over DNS for the KDCs in the realms. This is configuration issue on your side.

Please do not reopen the ticket. Instead, please use freeipa-users@ mailing list to communicate with your configuration issues.

Metadata Update from @abbra:
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)

Note that if you are using recent SSSD, there is no need to add auth_to_local stanza. In general, following https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/7/html-single/windows_integration_guide/index is better than looking at wiki pages that might be outdated.
Metadata
None
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.