(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [become_user] (0x0200): Already user [0].
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [main] (0x2000): Running as [0][0].
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [main] (0x2000): getting TGT sync
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [GTWDCSMB$@mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.690452: Getting initial credentials for GTWDCSMB$@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.690570: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.690610: Sending request (188 bytes) to mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.690803: Sending initial UDP request to dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691741: Received answer (201 bytes) from dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691816: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691848: Received error from KDC: -1765328359/Additional pre-authentication required

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691891: Processing preauth types: 16, 15, 19, 2

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691904: Selected etype info: etype aes256-cts, salt "mydc.COMhostgtwdcsmb.mydc.com", params ""

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691931: Retrieving GTWDCSMB$@mydc.COM from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.691960: AS key obtained for encrypted timestamp: aes256-cts/68CD

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.692019: Encrypted timestamp (for 1461411851.104595): plain 301AA011180F32303136303432333131343431315AA1050203019893, encrypted 6D0CE59ABD070E2C3536D4DB47668B013689A266A30256B198D7F1F621BAD4DC0A3662E72E52827BA6B2D28DFF322AADF4DC9A7C4DA89514

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.692037: Preauth module encrypted_timestamp (2) (real) returned: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.692045: Produced preauth for next request: 2

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.692060: Sending request (268 bytes) to mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.692097: Sending initial UDP request to dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693323: Received answer (1445 bytes) from dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693424: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693463: Processing preauth types: 19

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693486: Selected etype info: etype aes256-cts, salt "mydc.COMhostgtwdcsmb.mydc.com", params ""

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693501: Produced preauth for next request: (empty)

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693518: AS key determined by preauth: aes256-cts/68CD

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693587: Decrypted AS reply; session key is: aes256-cts/36C8

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693598: FAST negotiation: unavailable

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_mydc.COM_Rwiieh]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.693669: Initializing FILE:/var/lib/sss/db/ccache_mydc.COM_Rwiieh with default princ GTWDCSMB$@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [sss_child_krb5_trace_cb] (0x4000): [4240] 1461411849.703714: Storing GTWDCSMB$@mydc.COM -> krbtgt/mydc.COM@mydc.COM in FILE:/var/lib/sss/db/ccache_mydc.COM_Rwiieh

(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_mydc.COM_Rwiieh] to [/var/lib/sss/db/ccache_mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [prepare_response] (0x0400): Building response for result [0]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [pack_buffer] (0x2000): response size: 59
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [39] msg [FILE:/var/lib/sss/db/ccache_mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[ldap_child[4240]]]] [main] (0x0400): ldap_child completed successfully
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x1000): Waiting for child [4240].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x0100): child [4240] finished successfully.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_mydc.COM], expired on [1461447849]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1461412749
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: GTWDCSMB$
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2036
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_set_port_status] (0x0100): Marking port 3268 of server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [set_server_common_status] (0x0100): Marking server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_set_port_status] (0x0400): Marking port 3268 of duplicate server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_user_data_cmp] (0x1000): Comparing GC with GC
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_done] (0x2000): Old USN: 16808, New USN: 16821
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [DC=mydc,DC=com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=test12345)(objectclass=user)(objectSID=*))][DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 5 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fdccd0], connected[1], ops[0x7f2f83fdc350], ldap[0x7f2f83fdbe40]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=test12345,CN=Users,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fdccd0], connected[1], ops[0x7f2f83fdc350], ldap[0x7f2f83fdbe40]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 5 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_user] (0x4000): Storing the user
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x0400): Save user
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_primary_name] (0x0400): Processing object test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x0400): Processing user test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x1000): Mapping user [test12345] objectSID [S-1-5-21-2043037144-1837054757-106619645-1107] to unix ID
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=test12345,CN=Users,DC=mydc,DC=com] to attributes of [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20160423105901.0Z] to attributes of [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x0400): Adding user principal [test12345@mydc.COM] to attributes of [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [66048] to attributes of [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_user] (0x0400): Storing info for user test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84001620

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840016e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84001620 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840016e0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84001620 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83fcd500

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83fcd5c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83fcd500 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83fcd5c0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83fcd500 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84001d90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840077b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84001d90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840077b0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84001d90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f840033b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840077b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f840033b0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840077b0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f840033b0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84009610

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84003f90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84009610 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84003f90 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84009610 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84003f90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84003c20

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84003f90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84003c20 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84003f90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_user] (0x4000): Commit change
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84001540

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84001670

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84001540 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84001670 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84001540 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_user] (0x4000): Process user's groups
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=test12345,CN=Users,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 11
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 11 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fdccd0], connected[1], ops[(nil)], ldap[0x7f2f83fdbe40]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=test12345,CN=Users,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [tokenGroups]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 11 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-32-544]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_idmap_sid_to_unix] (0x0400): Object SID [S-1-5-32-544] is a built-in one.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x0400): Skipping built-in object.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-32-545]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_idmap_sid_to_unix] (0x0400): Object SID [S-1-5-32-545] is a built-in one.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x0400): Skipping built-in object.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-21-2043037144-1837054757-106619645-572]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): SID [S-1-5-21-2043037144-1837054757-106619645-572] maps to GID [309400572]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84001710

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84003430

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84001710 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84003430 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84001710 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-21-2043037144-1837054757-106619645-1106]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): SID [S-1-5-21-2043037144-1837054757-106619645-1106] maps to GID [309401106]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ffa210

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffa2d0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ffa210 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffa2d0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ffa210 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-21-2043037144-1837054757-106619645-513]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): SID [S-1-5-21-2043037144-1837054757-106619645-513] maps to GID [309400513]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff7e10

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840022b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff7e10 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840022b0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff7e10 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): Processing membership SID [S-1-5-21-2043037144-1837054757-106619645-512]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_initgr_mapping_done] (0x1000): SID [S-1-5-21-2043037144-1837054757-106619645-512] maps to GID [309400512]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84002370

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff7d50

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84002370 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff7d50 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84002370 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff7d50

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff7e10

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff7d50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff7e10 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff7d50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84002370

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff7d50

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84002370 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff91c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff9280

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff7d50 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84002370 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff91c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ffb3e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffb4a0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff9280 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff91c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ffb3e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84016150

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84017b90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffb4a0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ffb3e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84016150 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f840166c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84016780

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84017b90 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84016150 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f840166c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f840174f0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840175b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84016780 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f840166c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f840174f0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8401a520

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f8401a5e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840175b0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f840174f0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8401a520 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8401acd0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f8401ad90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f8401a5e0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8401a520 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8401acd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ffb040

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84015550

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f8401ad90 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8401acd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ffb040 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84015550 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ffb040 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_done] (0x4000): Initgroups done
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_initgr_done] (0x1000): Mapping primary group to unix ID
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [DC=mydc,DC=com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectSID=S-1-5-21-2043037144-1837054757-106619645-513)(objectClass=group)(sAMAccountName=*))][DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [groupType]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 12
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 12 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=Domain Users,CN=Users,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [groupType]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.mydc.com/DC=ForestDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.mydc.com/DC=DomainDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff65a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 12 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://ForestDnsZones.mydc.com/DC=ForestDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://DomainDnsZones.mydc.com/DC=DomainDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_has_deref_support] (0x0400): The server supports deref method ASQ
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_check_ad_group_type] (0x4000): AD group [] has type flags 0x80000002.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_hash_group] (0x4000): The group's gid was zero
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_hash_group] (0x2000): Marking group as non-posix and setting GID=0!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_hash_insert] (0x4000): Inserting [CN=Domain Users,CN=Users,DC=mydc,DC=com] into hash table [groups]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_process_send] (0x2000): About to process group [CN=Domain Users,CN=Users,DC=mydc,DC=com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_recv] (0x0400): 0 users found in the hash table
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_group_recv] (0x0400): 1 groups found in the hash table
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_primary_name] (0x0400): Processing object Domain Users
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_group] (0x0400): Processing group Domain Users
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_check_ad_group_type] (0x4000): AD group [Domain Users] has type flags 0x80000002.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_group] (0x1000): Mapping group [Domain Users] objectSID [S-1-5-21-2043037144-1837054757-106619645-513] to unix ID
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [CN=Domain\20Users,CN=Users,DC=mydc,DC=com] to attributes of [Domain Users].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20160423105836.0Z] to attributes of [Domain Users].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_ghost_members] (0x0400): The group has 0 members
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_ghost_members] (0x0400): Group has 0 members
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_group] (0x0400): Storing info for group Domain Users
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f840171b0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840172e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f840171b0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840172e0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f840171b0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84004b20

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84004be0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84004b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff8720

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffc260

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84004be0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84004b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff8720 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ffd220

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffd2e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffc260 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff8720 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ffd220 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffd2e0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ffd220 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_groups] (0x4000): Group 0 processed!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_primary_name] (0x0400): Processing object Domain Users
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_grpmem] (0x0400): Processing group Domain Users
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_search_users] (0x2000): Search users with filter: (&(objectclass=user)(gidNumber=309400513))
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8401a2c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffbe10

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffbe10 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_grpmem] (0x0400): Adding member users to group [Domain Users]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8401a2c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ffc6a0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ffc6a0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8401a2c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840031a0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f840049c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84004a80

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840031a0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8401a2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f840049c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84010e40

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84010f00

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84004a80 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f840049c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84010e40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ffd2c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84016330

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84010f00 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84010e40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ffd2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84013300

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84016c50

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84016330 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ffd2c0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84013300 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84016c50 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84013300 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_save_groups] (0x4000): Group 0 members processed!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_nested_done] (0x2000): No external members, done(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff6cc0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff3900

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff6cc0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff3900 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff6cc0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff1a60

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff0770

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff1a60 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff0770 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff1a60 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_add_timeout] (0x2000): 0x7f2f83fd9f70
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[(nil)], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x7f363e33c940
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider_rev.initgrCheck on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_memcache_initgr_check] (0x1000): Got request for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e3449e0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e351e70

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e3449e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e351e70 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e3449e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e33c8e0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e340bf0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e33c8e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e34c3e0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e34c510

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e340bf0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e33c8e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e34c3e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e33b570

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e33acb0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e34c510 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e34c3e0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e33b570 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e343d00

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e3526a0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e33acb0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e33b570 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e343d00 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e33acb0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e351fa0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e3526a0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e343d00 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e33acb0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e352060

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e34d680

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e351fa0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e33acb0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e352060 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e34d680 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e352060 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_remove_timeout] (0x2000): 0x7f2f83fd9f70
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc30f0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Success)
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc13df0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Success)
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc1bf50

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc1c080

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc1bf50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc1c080 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc1bf50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [test12345] added to PAM initgroup cache
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7ffaccc17be0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7ffacb1c8090:3:test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc5b50
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_req_set_domain] (0x0400): Changing request domain from [mydc.com] to [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Got request with the following data
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): ruser:
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): authtok type: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): logon name: not set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [test12345] is empty, running request [0x7f2f83fca270] immediately.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [krb5_setup] (0x4000): No mapping for: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff0d40

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff60e0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff0d40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff60e0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff0d40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [krb5_auth_send] (0x0100): Home directory for user [test12345] not known.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [get_server_status] (0x1000): Status of server 'DC02.mydc.com' is 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'DC02.mydc.com' is 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [get_server_status] (0x1000): Status of server 'DC02.mydc.com' is 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_resolve_server_process] (0x0200): Found address for server DC02.mydc.com: [192.168.100.2] TTL 3600
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://DC02.mydc.com'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://DC02.mydc.com'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sss_krb5_realm_has_proxy] (0x0040): profile_get_values failed.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [4241]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [4241]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [main] (0x0400): krb5_child started.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [unpack_buffer] (0x1000): total buffer size: [154]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [unpack_buffer] (0x0100): cmd [241] uid [309401107] gid [309400513] validate [true] enterprise principal [true] offline [false] UPN [test12345@mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:309401107] old_ccname: [KEYRING:persistent:309401107] keytab: [/etc/krb5.keytab]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [check_use_fast] (0x0100): Not using FAST.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [switch_creds] (0x0200): Switch user to [309401107][309400513].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [switch_creds] (0x0200): Switch user to [0][0].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:309401107] and is not active and TGT is  valid.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [become_user] (0x0200): Trying to become user [309401107][309400513].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [main] (0x2000): Running as [309401107][309400513].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [k5c_setup] (0x2000): Running as [309401107][309400513].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [main] (0x0400): Will perform online auth
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [mydc.COM]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.746521: Getting initial credentials for test12345\@mydc.COM@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.746650: Sending request (200 bytes) to mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.746876: Sending initial UDP request to dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.748096: Received answer (186 bytes) from dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.748167: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.748198: Received error from KDC: -1765328359/Additional pre-authentication required

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.748230: Processing preauth types: 16, 15, 19, 2

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.748248: Selected etype info: etype aes256-cts, salt "mydc.COMtest12345", params ""

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760148: AS key obtained for encrypted timestamp: aes256-cts/7D6A

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760230: Encrypted timestamp (for 1461411851.178973): plain 301AA011180F32303136303432333131343431315AA105020302BB1D, encrypted DF1AAF9D395BA3CB8C140FED5A4366D8F0FC178CC8CBACEAC8D60D81B0D1822ADBB8C74C69FADA3E456B57675CD6BA3C28B2433685FAC301

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760254: Preauth module encrypted_timestamp (2) (real) returned: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760263: Produced preauth for next request: 2

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760280: Sending request (280 bytes) to mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.760332: Sending initial UDP request to dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761616: Received answer (94 bytes) from dgram 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761724: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761751: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761764: Request or response is too big for UDP; retrying with TCP

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761772: Sending request (280 bytes) to mydc.COM (tcp only)

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.761811: Initiating TCP connection to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.762104: Sending TCP request to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.762977: Received answer (1484 bytes) from stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763001: Terminating TCP connection to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763063: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763098: Processing preauth types: 19

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763117: Selected etype info: etype aes256-cts, salt "mydc.COMtest12345", params ""

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763134: Produced preauth for next request: (empty)

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763151: AS key determined by preauth: aes256-cts/7D6A

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763216: Decrypted AS reply; session key is: aes256-cts/CBA9

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763227: FAST negotiation: unavailable

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [675097436]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763291: Retrieving host/gtwdcsmb.mydc.com@mydc.COM from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763301: Resolving unique ccache of type MEMORY

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763318: Initializing MEMORY:quO8Ru9 with default princ test12345@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763328: Storing test12345@mydc.COM -> krbtgt/mydc.COM@mydc.COM in MEMORY:quO8Ru9

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763345: Getting credentials test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM using ccache MEMORY:quO8Ru9

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763368: Retrieving test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM from MEMORY:quO8Ru9 with result: -1765328243/Matching credential not found

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763386: Retrieving test12345@mydc.COM -> krbtgt/mydc.COM@mydc.COM from MEMORY:quO8Ru9 with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763395: Starting with TGT for client realm: test12345@mydc.COM -> krbtgt/mydc.COM@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763404: Requesting tickets for host/gtwdcsmb.mydc.com@mydc.COM, referrals on

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763421: Generated subkey for TGS request: aes256-cts/466C

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763520: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763600: Encoding request body and padata into FAST request

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763667: Sending request (1665 bytes) to mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.763727: Initiating TCP connection to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.764165: Sending TCP request to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.765812: Received answer (1472 bytes) from stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.765869: Terminating TCP connection to stream 192.168.100.2:88

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.765960: Response was from master KDC

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766022: Decoding FAST response

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766132: TGS reply is for test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM with session key aes256-cts/4445

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766165: TGS request result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766179: Received creds for desired service host/gtwdcsmb.mydc.com@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766195: Storing test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM in MEMORY:quO8Ru9

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766242: Creating authenticator for test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM, seqnum 0, subkey (null), session key aes256-cts/4445

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766315: Retrieving host/gtwdcsmb.mydc.com@mydc.COM from MEMORY:/etc/krb5.keytab (vno 1, enctype aes256-cts) with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766378: Decrypted AP-REQ with specified server principal host/gtwdcsmb.mydc.com@mydc.COM: aes256-cts/68CD

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766398: AP-REQ ticket: test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM, session key aes256-cts/4445

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766720: Negotiated enctype based on authenticator: aes256-cts

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766752: Initializing MEMORY:rd_req2 with default princ test12345@mydc.COM

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766774: Storing test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM in MEMORY:rd_req2

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766799: Destroying ccache MEMORY:quO8Ru9

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [validate_tgt] (0x0400): TGT verified using key for [host/gtwdcsmb.mydc.com@mydc.COM].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766841: Retrieving test12345@mydc.COM -> host/gtwdcsmb.mydc.com@mydc.COM from MEMORY:rd_req2 with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766914: Retrieving host/gtwdcsmb.mydc.com@mydc.COM from MEMORY:/etc/krb5.keytab (vno 1, enctype aes256-cts) with result: 0/Success

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][2].
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [test12345\@mydc.COM@mydc.COM] might not be correct.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_child_krb5_trace_cb] (0x4000): [4241] 1461411849.766989: Destroying ccache MEMORY:rd_req2

(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [KEYRING:persistent:309401107]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname: [KEYRING:persistent:309401107:krb_ccache_1IjKXTv]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [create_ccache] (0x4000): Initializing ccache of type [KEYRING]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [create_ccache] (0x4000): CC supports switch
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [create_ccache] (0x4000): returning: 0
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the same, none will be deleted.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [k5c_send_data] (0x0200): Received error code 0
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [pack_response_packet] (0x2000): response packet size: [138]
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [k5c_send_data] (0x4000): Response sent.
(Sat Apr 23 13:44:09 2016) [[sssd[krb5_child[4241]]]] [main] (0x0400): krb5_child completed successfully
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x1000): Waiting for child [4241].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x0100): child [4241] finished successfully.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [parse_krb5_child_response] (0x1000): child response [0][3][40].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [parse_krb5_child_response] (0x1000): child response [0][-1073741822][22].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [parse_krb5_child_response] (0x1000): child response [0][-1073741823][32].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [parse_krb5_child_response] (0x1000): TGT times are [1461411852][1461411852][1461447852][1461447852].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [parse_krb5_child_response] (0x1000): child response [0][6][8].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1039
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [set_server_common_status] (0x0100): Marking server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_user_data_cmp] (0x1000): Comparing LDAP with LDAP
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'DC02.mydc.com' as 'working'
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_user_data_cmp] (0x1000): Comparing LDAP with LDAP
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:309401107] for user [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f83ff3170

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f83ff7540

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f83ff3170 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f83ff7540 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f83ff3170 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84014360

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84014490

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84014360 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84014490 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84014360 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [check_wait_queue] (0x1000): Wait queue for user [test12345] is empty.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7f2f83fca270] done.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Sending result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Sent result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc17be0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc26340

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc26470

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc26340 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc26470 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc26340 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 76
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e3429d0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342b00

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e3429d0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342b00 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e3429d0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_cmd_acct_mgmt] (0x0100): entering pam_cmd_acct_mgmt
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_initgr_check_timeout] (0x2000): User [test12345] found in PAM cache.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc19b20

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc1c3c0

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc1c3c0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc5b50
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_req_set_domain] (0x0400): Changing request domain from [mydc.com] to [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Got request with the following data
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): ruser:
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): logon name: not set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_access_send] (0x0400): Performing access check for user [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84013200

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f840132c0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84013200 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f840132c0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84013200 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_account_expired_ad] (0x0400): Performing AD access check for user [test12345]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_account_expired_ad] (0x4000): User account control for user [test12345] is [10200].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_account_expired_ad] (0x4000): Expiration time for user [test12345] is [0].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_access_send] (0x0400): service sshd maps to Remote Interactive
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_connect_done] (0x4000): server_hostname from uri: DC02.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_connect_done] (0x0400): sam_account_name is GTWDCSMB$
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=user)(sAMAccountName=GTWDCSMB$))][dc=mydc,dc=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [distinguishedName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 13
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 13 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=GTWDCSMB,OU=gateway,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [distinguishedName]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.mydc.com/DC=ForestDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.mydc.com/DC=DomainDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 13 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://ForestDnsZones.mydc.com/DC=ForestDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [generic_ext_search_handler] (0x4000):     Ref: ldap://DomainDnsZones.mydc.com/DC=DomainDnsZones,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [objectclass=domain][DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 14
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 14 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 14 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_master_domain_next_done] (0x0400): Found SID [S-1-5-21-2043037144-1837054757-106619645].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=mydc.com)(NtVer=\14\00\00\00))][].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 15
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 15 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netlogon]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 15 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_master_domain_netlogon_done] (0x0400): Found flat name [mydcOM].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_master_domain_netlogon_done] (0x0400): Found site [Default-First-Site-Name].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_master_domain_netlogon_done] (0x0400): Found forest [mydc.com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [configurationNamingContext]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 16
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 16 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83f8dc50], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 16 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[0]->som_dn is OU=gateway,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[1]->som_dn is DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[2]->som_dn is cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][OU=gateway,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 17
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 17 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f84008b10], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [OU=gateway,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPLink]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f84008b10], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 17 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_get_som_attrs_done] (0x4000): gpoptions attr not found or has no value; defaults to 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_gplink_list] (0x0400): som_dn: OU=gateway,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_gplink_list] (0x4000): gplink_list[0]: [cn={5C320202-3B01-4865-B495-395BD580B315},cn=policies,cn=system,DC=mydc,DC=com; 0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 18
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 18 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff41a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPLink]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff41a0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 18 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_get_som_attrs_done] (0x4000): gpoptions attr not found or has no value; defaults to 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_gplink_list] (0x0400): som_dn: DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_gplink_list] (0x4000): gplink_list[0]: [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydc,DC=com; 0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 19
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 19 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f84008bd0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): Entry has no attributes [0(Success)]!?
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f84008bd0], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 19 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_get_som_attrs_done] (0x0040): no attrs found for SOM; try next SOM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_candidate_gpos] (0x0400): candidate_gpos[0]->gpo_dn: CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_populate_candidate_gpos] (0x0400): candidate_gpos[1]->gpo_dn: cn={5C320202-3B01-4865-B495-395BD580B315},cn=policies,cn=system,DC=mydc,DC=com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_sd_search_send] (0x0400): Searching entry [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydc,DC=com] using SD
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nTSecurityDescriptor]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFileSysPath]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCMachineExtensionNames]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFunctionalityVersion]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flags]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 20
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 20 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff5f80], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [nTSecurityDescriptor]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [flags]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCFunctionalityVersion]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCFileSysPath]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCMachineExtensionNames]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f83ff5f80], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 20 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): populating attrs for gpo_guid: {31B2F340-016D-11D2-945F-00C04FB984F9}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_extract_smb_components] (0x4000): input_path: \\mydc.com\sysvol\mydc.com\Policies\{31B2F340-016D-11D2-945F-00C04FB984F9}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_server: smb://DC02.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_share: /sysvol
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_path: /mydc.com/Policies/{31B2F340-016D-11D2-945F-00C04FB984F9}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): gpo_func_version: 2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): gpo_flags: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): num_gpo_cse_guids: 3
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): gpo_cse_guids[0] is {35378EAC-683F-11D2-A89A-00C04FBBCFA2}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): gpo_cse_guids[1] is {827D319E-6EAC-11D2-A4EA-00C04F79F83A}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): gpo_cse_guids[2] is {B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_sd_search_send] (0x0400): Searching entry [cn={5C320202-3B01-4865-B495-395BD580B315},cn=policies,cn=system,DC=mydc,DC=com] using SD
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_print_server] (0x2000): Searching 192.168.100.2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][cn={5C320202-3B01-4865-B495-395BD580B315},cn=policies,cn=system,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nTSecurityDescriptor]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFileSysPath]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCMachineExtensionNames]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFunctionalityVersion]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flags]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 21
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_add] (0x2000): New operation 21 timeout 6
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f8400ac00], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f8400ac00], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn={5C320202-3B01-4865-B495-395BD580B315},cn=policies,cn=system,DC=mydc,DC=com].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [nTSecurityDescriptor]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [flags]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCFunctionalityVersion]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCFileSysPath]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [gPCMachineExtensionNames]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[0x7f2f8400ac00], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_op_destructor] (0x2000): Operation 21 finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): populating attrs for gpo_guid: {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_extract_smb_components] (0x4000): input_path: \\mydc.com\SysVol\mydc.com\Policies\{5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_server: smb://DC02.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_share: /SysVol
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): smb_path: /mydc.com/Policies/{5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): gpo_func_version: 2
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_sd_process_attrs] (0x4000): gpo_flags: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): num_gpo_cse_guids: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_parse_machine_ext_names] (0x4000): gpo_cse_guids[0] is {827D319E-6EAC-11D2-A4EA-00C04F79F83A}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84015d90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84016bb0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84015d90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84016bb0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84015d90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84008dd0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84019ec0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84008dd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84011800

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84011930

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84019ec0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84008dd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84011800 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f8400b290

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84012620

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84011930 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84011800 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f8400b290 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84011740

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84012f90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84012620 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f8400b290 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84011740 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84012620

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f8400b290

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84012f90 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84011740 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84012620 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84016d50

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84011dc0

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f8400b290 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84012620 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84016d50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84011dc0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84016d50 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_dacl] (0x4000): examining dacl candidate_gpo_guid:{31B2F340-016D-11D2-945F-00C04FB984F9}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_dacl] (0x4000): GPO not applicable to target per security filtering
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_dacl] (0x4000): examining dacl candidate_gpo_guid:{5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_dacl] (0x4000): GPO applicable to target per security filtering
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_process_gpo_done] (0x0400): dacl_filtered_gpos[0]->gpo_guid is {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_cse_guid] (0x4000): examining cse candidate_gpo_guid: {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_filter_gpos_by_cse_guid] (0x4000): GPO applicable to target per cse_guid filtering
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_process_gpo_done] (0x0400): cse_filtered_gpos[0]->gpo_guid is {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_process_gpo_done] (0x0400): num_cse_filtered_gpos: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_gpo_get_gpo_result_object] (0x4000): cn=gpos,cn=ad,cn=custom,cn=mydc.com,cn=sysdb
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84015c90

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f84009f00

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84015c90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f84009f00 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84015c90 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_gpo_get_gpo_result_object] (0x4000): No GPO Result object.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): cse filtered_gpos[0]->gpo_guid is {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x4000): cse_filtered_gpos[0]->gpo_cse_guids[0]->gpo_guid is {827D319E-6EAC-11D2-A4EA-00C04F79F83A}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): smb_server: smb://DC02.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): smb_share: /SysVol
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): smb_path: /mydc.com/Policies/{5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): gpo_guid: {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): retrieving GPO from cache [{5C320202-3B01-4865-B495-395BD580B315}]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_gpo_get_gpo_by_guid] (0x4000): cn=gpos,cn=ad,cn=custom,cn=mydc.com,cn=sysdb
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2f84009f80

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2f8400b290

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Running timer event 0x7f2f84009f80 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Destroying timer event 0x7f2f8400b290 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ldb] (0x4000): Ending timer event 0x7f2f84009f80 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sysdb_gpo_get_gpo_by_guid] (0x4000): No such entry.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): ENOENT
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): send_to_child: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_step] (0x0400): cached_gpt_version: -1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [create_cse_send_buffer] (0x4000): buffer size: 158
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [4243]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [4243]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: sh[0x7f2f83fcae70], connected[1], ops[(nil)], ldap[0x7f2f83f91be0]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [main] (0x0400): gpo_child started.
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [main] (0x0400): context initialized
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x0400): cached_gpt_version: -1
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_server length: 22
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_server: smb://DC02.mydc.com
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_share length: 7
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_share: /SysVol
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_path length: 60
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_path: /mydc.com/Policies/{5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_cse_suffix length: 49
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [unpack_buffer] (0x4000): smb_cse_suffix: /Machine/Microsoft/Windows NT/SecEdit/GptTmpl.inf
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [main] (0x0400): performing smb operations
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [copy_smb_file_to_gpo_cache] (0x0400): smb_uri: smb://DC02.mydc.com/SysVol/mydc.com/Policies/{5C320202-3B01-4865-B495-395BD580B315}/GPT.INI
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [copy_smb_file_to_gpo_cache] (0x0020): smbc_getFunctionOpen failed [2][No such file or directory]
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [perform_smb_operations] (0x0020): copy_smb_file_to_gpo_cache failed [2][No such file or directory]
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [main] (0x0020): perform_smb_operations failed.[2][No such file or directory].
(Sat Apr 23 13:44:09 2016) [[sssd[gpo_child[4243]]]] [main] (0x0020): gpo_child failed!
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [gpo_cse_done] (0x0020): ad_gpo_parse_gpo_child_response failed: [22][Invalid argument]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_done] (0x0400): gpo_guid: {5C320202-3B01-4865-B495-395BD580B315}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_cse_done] (0x0040): Unable to retrieve policy data: [22](Invalid argument}
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_access_done] (0x0040): GPO-based access control failed.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [ad_gpo_access_done] (0x0040): Ignoring error: [22](Invalid argument); GPO-based access control failed, but GPO is not in enforcing mode.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0400): SELinux provider doesn't exist, not sending the request to it.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Sending result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler_callback] (0x0100): Sent result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x1000): Waiting for child [4243].
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [child_sig_handler] (0x0020): child [4243] failed with status [1].
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 28
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [38] with input [test12345@mydc.com].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345@mydc.com' matched expression for domain 'mydc.com', user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e346cf0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e340ef0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e346cf0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e353c40

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e353d70

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e340ef0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e346cf0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e353c40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e346cf0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e340ef0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e353d70 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e353c40 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e346cf0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e353d70

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e3542f0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e340ef0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e346cf0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e353d70 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e343b80

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e346cf0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e3542f0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e353d70 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e343b80 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e353d70

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e353bf0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e346cf0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e343b80 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e353d70 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e353bf0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e353d70 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for [test12345@mydc.com] completed
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_cmd_setcred] (0x0100): entering pam_cmd_setcred
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_initgr_check_timeout] (0x2000): User [test12345] found in PAM cache.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc19b20

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc1c3c0

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc1c3c0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc5b50
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_req_set_domain] (0x0400): Changing request domain from [mydc.com] to [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Got request with the following data
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): ruser:
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): logon name: not set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Sending result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 28
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_cmd_open_session] (0x0100): entering pam_cmd_open_session
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_initgr_check_timeout] (0x2000): User [test12345] found in PAM cache.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc19b20

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc1c3c0

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc1c3c0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc19b20 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc5b50
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_req_set_domain] (0x0400): Changing request domain from [mydc.com] to [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Got request with the following data
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): ruser:
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): priv: 1
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): cli_pid: 4238
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): logon name: not set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Sending result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc16a20
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 28
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc15240][17]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [test12345].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [test12345] from [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e342830

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e342960

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e342960 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e342830 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e33df10][19]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[309400513] pid[4245].
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc194b0][18]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected!
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc194b0][18]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc194b0][18]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc194b0][18]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_cmd_setcred] (0x0100): entering pam_cmd_setcred
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'test12345' matched without domain, user is test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4245
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mydc.com/test12345]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_initgr_check_timeout] (0x2000): User [test12345] found in PAM cache.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7ffaccc1c4f0

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7ffaccc18460

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7ffaccc1c4f0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7ffaccc18460 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7ffaccc1c4f0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [test12345@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 4245
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: test12345
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7ffaccc16bd0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83fc5b50
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_req_set_domain] (0x0400): Changing request domain from [mydc.com] to [mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Got request with the following data
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): command: PAM_SETCRED
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): domain: mydc.COM
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): user: test12345
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): service: sshd
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): tty: ssh
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): ruser:
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): rhost: client01.mydc.com
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): authtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): newauthtok type: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): priv: 0
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): cli_pid: 4245
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [pam_print_data] (0x0100): logon name: not set
(Sat Apr 23 13:44:09 2016) [sssd[be[mydc.com]]] [be_pam_handler] (0x0100): Sending result [0][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7ffaccc16bd0
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc0f810
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [0 (Success)][mydc.COM]
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]: Success.
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 28
(Sat Apr 23 13:44:09 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7ffaccc194b0][18]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[309401107] egid[309400513] pid[4252].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getbyid] (0x0400): Running command [34] with id [309400513].
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GID/309400513]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [309400513@mydc.com]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f363e340bd0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f363e3471d0

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f363e340bd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f363e3471d0 "ltdb_timeout"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f363e340bd0 "ltdb_callback"

(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0010): getgrgid call returned more than one result !?!
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GID/309400513] to negative cache
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [309400513]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f363e346fd0][20]
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Sat Apr 23 13:44:09 2016) [sssd[nss]] [client_destructor] (0x2000): Terminated client [0x7f363e346fd0][20]
<(Sat Apr 23 13:44:14 2016) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [test12345] removed from PAM initgroup cache
(Sat Apr 23 13:44:16 2016) [sssd] [service_send_ping] (0x0100): Pinging mydc.com
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_add_timeout] (0x2000): 0x7f64c98fe710
(Sat Apr 23 13:44:16 2016) [sssd] [service_send_ping] (0x0100): Pinging nss
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_add_timeout] (0x2000): 0x7f64c98fc4c0
(Sat Apr 23 13:44:16 2016) [sssd] [service_send_ping] (0x0100): Pinging pam
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_add_timeout] (0x2000): 0x7f64c98fc500
(Sat Apr 23 13:44:16 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2f83f8dfc0
(Sat Apr 23 13:44:16 2016) [sssd[be[mydc.com]]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x7f363e33b120
(Sat Apr 23 13:44:16 2016) [sssd[be[mydc.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path /org/freedesktop/sssd/service
(Sat Apr 23 13:44:16 2016) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd[be[mydc.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:16 2016) [sssd[nss]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path /org/freedesktop/sssd/service
(Sat Apr 23 13:44:16 2016) [sssd[nss]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_remove_timeout] (0x2000): 0x7f64c98fe710
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f64c98fdbb0
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd] [ping_check] (0x0100): Service mydc.com replied to ping
(Sat Apr 23 13:44:16 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7ffaccc10a70
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_remove_timeout] (0x2000): 0x7f64c98fc4c0
(Sat Apr 23 13:44:16 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f64c98ff340
(Sat Apr 23 13:44:16 2016) [sssd[pam]] [sbus_message_handler] (0x2000): (Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): Received SBUS method org.freedesktop.sssd.service.ping on path /org/freedesktop/sssd/service
Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd] [ping_check] (0x0100): Service nss replied to ping
(Sat Apr 23 13:44:16 2016) [sssd[pam]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_remove_timeout] (0x2000): 0x7f64c98fc500
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f64c9901180
(Sat Apr 23 13:44:16 2016) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Sat Apr 23 13:44:16 2016) [sssd] [ping_check] (0x0100): Service pam replied to ping