[Freeipa-users] performance scaling of sssd / freeipa

Fri Jan 20 19:34:55 UTC 2017

Sumit,

As per your request here are the sssd logs between 08:42:34 and 08:43:34.  It looks like a SIGHUP was received in sssd.log.   I was a little surprised to see that SIGHUP, but I tested and I can actually reproduce it (I reproduced it twice).   The 8:42:32 log entry in sssd.log is the last entry in that log (the other log files for example the domain logs, have additional data past this point in time).  FWIW all of the 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu> in all the logs are the same user (the user that I am doing parallel lookups on).  I really appreciate your help with this.

Thank you,

Dan

krb5_child.log

(Fri Jan 20 06:51:10 2017) [[sssd[krb5_child[11054]]]] [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the same, none will be deleted.
(Fri Jan 20 06:51:10 2017) [[sssd[krb5_child[11054]]]] [k5c_send_data] (0x0200): Received error code 0
(Fri Jan 20 06:51:10 2017) [[sssd[krb5_child[11054]]]] [pack_response_packet] (0x2000): response packet size: [151]
(Fri Jan 20 06:51:10 2017) [[sssd[krb5_child[11054]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Jan 20 06:51:10 2017) [[sssd[krb5_child[11054]]]] [main] (0x0400): krb5_child completed successfully
(Fri Jan 20 11:18:54 2017) [[sssd[krb5_child[25487]]]] [main] (0x0400): krb5_child started.
(Fri Jan 20 11:18:54 2017) [[sssd[krb5_child[25487]]]] [unpack_buffer] (0x1000): total buffer size: [66]
(Fri Jan 20 11:18:54 2017) [[sssd[krb5_child[25487]]]] [unpack_buffer] (0x0100): cmd [249] uid [339788572] gid [339788572] validate [true] enterprise principal [false] offline [false] UPN [user2 at ACTIVEDIRECTORY.UCHICAGO.EDU<mailto:user2 at ACTIVEDIRECTORY.UCHICAGO.EDU>]
(Fri Jan 20 11:18:54 2017) [[sssd[krb5_child[25487]]]] [k5c_setup_fast] (0x0100): SSSD_KRB5_FAST_PRINCIPAL is set to [host/cri-ksysipadcp2.cri.uchicago.edu at XXX.XXX.UCHICAGO.EDU<mailto:host/cri-ksysipadcp2.cri.uchicago.edu at XXX.XXX.UCHICAGO.EDU>]
(Fri Jan 20 11:18:54 2017) [[sssd[krb5_child[25487]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/cri-xxx.xxx.uchicago.edu at XXX.XXX.UCHICAGO.EDU<mailto:host/cri-xxx.xxx.uchicago.edu at XXX.XXX.UCHICAGO.EDU> in keytab.

ldap_child.log

(Fri Jan 20 08:40:37 2017) [[sssd[ldap_child[16889]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_ACTIVEDIRECTORY.UCHICAGO.EDU_Ml6iJF]
(Fri Jan 20 08:40:37 2017) [[sssd[ldap_child[16889]]]] [prepare_response] (0x0400): Building response for result [0]
(Fri Jan 20 08:40:37 2017) [[sssd[ldap_child[16889]]]] [pack_buffer] (0x2000): response size: 66
(Fri Jan 20 08:40:37 2017) [[sssd[ldap_child[16889]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [46] msg [FILE:/var/lib/sss/db/ccache_ACTIVEDIRECTORY.UCHICAGO.EDU]
(Fri Jan 20 08:40:37 2017) [[sssd[ldap_child[16889]]]] [main] (0x0400): ldap_child completed successfully
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [main] (0x0400): ldap_child started.
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [main] (0x2000): context initialized
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): total buffer size: 81
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): realm_str size: 20
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): got realm_str: XXX.XXX.UCHICAGO.EDU<http://xxx.xxx.uchicago.edu/>
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): princ_str size: 37
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): got princ_str: host/cri-ksysipadcp2.cri.uchicago.edu<http://cri-ksysipadcp2.cri.uchicago.edu/>
(Fri Jan 20 08:47:57 2017) [[sssd[ldap_child[17278]]]] [unpack_buffer] (0x1000): keytab_name size: 0

selinux_child.log

Fri Jan 20 06:51:11 2017) [[sssd[selinux_child[11055]]]] [seuser_needs_update] (0x2000): get_seuser: ret: 0 seuser: unconfined_u mls: s0-s0:c0.c1023
(Fri Jan 20 06:51:11 2017) [[sssd[selinux_child[11055]]]] [pack_buffer] (0x0400): result [0]
(Fri Jan 20 06:51:11 2017) [[sssd[selinux_child[11055]]]] [prepare_response] (0x4000): r->size: 4
(Fri Jan 20 06:51:11 2017) [[sssd[selinux_child[11055]]]] [main] (0x0400): selinux_child completed successfully
(Fri Jan 20 11:18:51 2017) [[sssd[selinux_child[25463]]]] [main] (0x0400): selinux_child started.
(Fri Jan 20 11:18:51 2017) [[sssd[selinux_child[25463]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jan 20 11:18:51 2017) [[sssd[selinux_child[25463]]]] [main] (0x2000): Running with real IDs [0][0].

sssd.log (last entry in file is from 08:42:32, other logs continue past this time)

(Fri Jan 20 08:42:32 2017) [sssd] [monitor_hup] (0x0020): Received SIGHUP.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdac1c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb4d30
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb4900
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb40c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb0260
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb32c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb4100
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_add_timeout] (0x2000): 0x7f00cbdb4330
(Fri Jan 20 08:42:32 2017) [sssd] [te_server_hup] (0x0020): Received SIGHUP. Rotating logfiles.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdac1c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbdad8a0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb4d30
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbdaaff0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb4900
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbdb09f0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb40c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda6700
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb0260
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda6290
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb32c0
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb4100
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda6290
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda6290
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda6290
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_remove_timeout] (0x2000): 0x7f00cbdb4330
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): dbus conn: 0x7f00cbda1a50
(Fri Jan 20 08:42:32 2017) [sssd] [sbus_dispatch] (0x4000): Dispatching.

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fccbcc6a880:1:user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>][0x1][BE_REQ_USER][1][name=user at activedirectory.uchicago.edu<mailto:name=user at activedirectory.uchicago.edu>:-]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x7fccbdd8c1b0
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fccbcc6a880:1:user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:42:43 2017) [sssd[nss]] [idle_handler] (0x2000): Terminating idle client [0x7fccbddc2c40][24]
(Fri Jan 20 08:42:43 2017) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x7fccbdd8c1b0
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getby_dp_callback] (0x0040): Unable to get information from Data Provider
Error: 3, 5, (null)
Will try to return what we have in cache

sssd_ssh.log

(Fri Jan 20 08:39:46 2017) [sssd[ssh]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 08:42:32 2017) [sssd[ssh]] [sbus_dispatch] (0x4000): dbus conn: 0x7f388a5f4e70
(Fri Jan 20 08:42:32 2017) [sssd[ssh]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd[ssh]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.rotateLogs on path /org/freedesktop/sssd/service
(Fri Jan 20 08:42:32 2017) [sssd[ssh]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 11:18:29 2017) [sssd[ssh]] [get_client_cred] (0x4000): Client creds: euid[99] egid[99] pid[25434].
(Fri Jan 20 11:18:29 2017) [sssd[ssh]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f388a606fc0][20]
(Fri Jan 20 11:18:29 2017) [sssd[ssh]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jan 20 11:18:29 2017) [sssd[ssh]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f388a606fc0][20]

sssd_sudo.log

(Fri Jan 20 08:39:46 2017) [sssd[sudo]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 08:42:32 2017) [sssd[sudo]] [sbus_dispatch] (0x4000): dbus conn: 0x7fc840028e70
(Fri Jan 20 08:42:32 2017) [sssd[sudo]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd[sudo]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.rotateLogs on path /org/freedesktop/sssd/service
(Fri Jan 20 08:42:32 2017) [sssd[sudo]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 11:18:54 2017) [sssd[sudo]] [get_client_cred] (0x4000): Client creds: euid[0] egid[339788572] pid[25486].
(Fri Jan 20 11:18:54 2017) [sssd[sudo]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fc8400366a0][20]
(Fri Jan 20 11:18:54 2017) [sssd[sudo]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jan 20 11:18:54 2017) [sssd[sudo]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fc8400366a0][20]

sssd_pam.log

(Fri Jan 20 08:39:46 2017) [sssd[pam]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 08:42:32 2017) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7fd2ab4f4e70
(Fri Jan 20 08:42:32 2017) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd[pam]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.rotateLogs on path /org/freedesktop/sssd/service
(Fri Jan 20 08:42:32 2017) [sssd[pam]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 11:18:44 2017) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[25432].
(Fri Jan 20 11:18:44 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fd2ab4fd180][21]
(Fri Jan 20 11:18:44 2017) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jan 20 11:18:44 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fd2ab4fd180][21]
(Fri Jan 20 11:18:44 2017) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].

sssd_pac.log

(Fri Jan 20 08:40:37 2017) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[495] egid[184] pid[6722].
(Fri Jan 20 08:40:37 2017) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [495].
(Fri Jan 20 08:42:32 2017) [sssd[pac]] [sbus_dispatch] (0x4000): dbus conn: 0x7f0351f38e70
(Fri Jan 20 08:42:32 2017) [sssd[pac]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:42:32 2017) [sssd[pac]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.rotateLogs on path /org/freedesktop/sssd/service
(Fri Jan 20 08:42:32 2017) [sssd[pac]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 08:46:28 2017) [sssd[pac]] [get_client_cred] (0x4000): Client creds: euid[495] egid[184] pid[6722].
(Fri Jan 20 08:46:28 2017) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [495].

domain logs

(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: sh[0x7f5b5c3eec20], connected[1], ops[0x7f5b5c3f7ed0], ldap[0x7f5b5c3df9a0]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_destructor] (0x2000): Operation 153 finished
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:AAA))].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 1/4
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_step] (0x1000): Fetching group BBB
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:BBB))].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_print_server] (0x2000): Searching 10.50.178.21:389
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:BBB))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=cri,dc=uchicago,dc=edu].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 154
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_add] (0x2000): New operation 154 timeout 60
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: sh[0x7f5b5c3eec20], connected[1], ops[0x7f5b5c3f7ed0], ldap[0x7f5b5c3df9a0]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: sh[0x7f5b5c3eec20], connected[1], ops[0x7f5b5c3f7ed0], ldap[0x7f5b5c3df9a0]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_destructor] (0x2000): Operation 154 finished
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:BBB))].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 2/4
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_step] (0x1000): Fetching group CCC
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:CCC))].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_print_server] (0x2000): Searching 10.50.178.21:389
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:CCC))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=cri,dc=uchicago,dc=edu].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 155
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_add] (0x2000): New operation 155 timeout 60
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: sh[0x7f5b5c3eec20], connected[1], ops[0x7f5b5c3f7ed0], ldap[0x7f5b5c3df9a0]
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sbus_dispatch] (0x4000): dbus conn: 0x7f5b5c3f8850
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=apache at domain]
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_attach_req] (0x0400): DP Request [Account #4293]: New request. Flags [0x0001].
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_attach_req] (0x0400): Number of active DP request: 2
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaUserOverride)(uid=apache))].
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_print_server] (0x2000): Searching 10.50.178.21:389
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=apache))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=cri,dc=uchicago,dc=edu].
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 156
(Fri Jan 20 08:43:30 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_add] (0x2000): New operation 156 timeout 60
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_timeout] (0x1000): Issuing timeout for 155
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_destructor] (0x1000): Abandoning operation 155
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_done] (0x0040): ipa_get_ad_override request failed.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_override_done] (0x0040): IPA override lookup failed: 110
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_id_get_groups_overrides_done] (0x0040): IPA resolve user groups overrides failed [110].
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [be_mark_dom_offline] (0x1000): Marking subdomain domain offline
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [be_mark_subdom_offline] (0x1000): Marking subdomain domain as inactive
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [110]: Connection timed out.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [110]: Connection timed out.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request?
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_done] (0x0400): DP Request [Account #4292]: Request handler finished [0]: Success
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [_dp_req_recv] (0x0400): DP Request [Account #4292]: Receiving request data.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #4292]: Finished. Success.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_reply_std] (0x1000): DP Request [Account #4292]: Returning [Success]: 0,110,Success
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1::domain:name=user at domain] from reply table
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_destructor] (0x0400): DP Request [Account #4292]: Request removed.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_destructor] (0x0400): Number of active DP request: 1

sssd_nss.log

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0040): No results for getpwnam call
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fccbcc6a880:1:user at xxx.xxx.uchicago.edu<mailto:user at xxx.xxx.uchicago.edu>@xxx.xxx.uchicago.edu]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbdd92820][25]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbdd92820][25]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x7fccbdd92820][25]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbdd99b80][23]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17][SSS_NSS_GETPWNAM] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user at activedirectory.uchicago.edu<mailto:NCE/USER/activedirectory.uchicago.edu/user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd88250

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd88250 "ltdb_callback"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd88250 "ltdb_callback"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd990f0

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc2330

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd990f0 "ltdb_callback"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc2330 "ltdb_timeout"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd990f0 "ltdb_callback"

(Fri Jan 20 08:42:32 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fccbcc6a880:1:user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>][0x1][BE_REQ_USER][1][name=user at activedirectory.uchicago.edu<mailto:name=user at activedirectory.uchicago.edu>:-]
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x7fccbdd8c1b0
(Fri Jan 20 08:42:32 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fccbcc6a880:1:user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:42:43 2017) [sssd[nss]] [idle_handler] (0x2000): Terminating idle client [0x7fccbddc2c40][24]
(Fri Jan 20 08:42:43 2017) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x7fccbdd8c1b0
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getby_dp_callback] (0x0040): Unable to get information from Data Provider
Error: 3, 5, (null)
Will try to return what we have in cache
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fccbcc6a880:1:user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbdd99b80][23]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbdd99b80][23]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17][SSS_NSS_GETPWNAM] with input [apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is apache
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [apache] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/apache at activedirectory.uchicago.edu<mailto:NCE/USER/activedirectory.uchicago.edu/apache at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd88250

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd80550

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd88250 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd80550 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd88250 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fccbcc6a880:1:apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>][0x1][BE_REQ_USER][1][name=apache at activedirectory.uchicago.edu<mailto:name=apache at activedirectory.uchicago.edu>:-]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x7fccbdd97300
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fccbcc6a880:1:apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>@activedirectory.uchicago.edu]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[495] egid[184] pid[6722].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbe15e7a0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd8f5f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbe15e7a0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd8f5f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbe15e7a0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd80650

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd92ee0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd80650 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd92ee0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd80650 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd92ee0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde1250

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd92ee0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde1250 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd92ee0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdd91da0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdde14f0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [277][SSS_NSS_GETORIGBYNAME] with input [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>].
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>' matched expression for domain 'activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>', user is user
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [user] from [activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/activedirectory.uchicago.edu/user<http://activedirectory.uchicago.edu/user>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Requesting info for [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbdd91da0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbdde14f0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbdde14f0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbdd91da0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fccbddc25e0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fccbddc0cd0

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7fccbddc0cd0 "ltdb_timeout"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7fccbddc25e0 "ltdb_callback"

(Fri Jan 20 08:43:30 2017) [sssd[nss]] [get_dp_name_and_id] (0x0400): Not a LOCAL view, continuing with provided values.
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [nss_cmd_getsidby_search] (0x0400): Returning info for user/group [user at activedirectory.uchicago.edu<mailto:user at activedirectory.uchicago.edu>]
(Fri Jan 20 08:43:30 2017) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7fccbddc2c40][24]
(Fri Jan 20 08:43:34 2017) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x7fccbdd840b0
(Fri Jan 20 08:43:34 2017) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Fri Jan 20 08:44:28 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x7fccbdd97300
(Fri Jan 20 08:44:28 2017) [sssd[nss]] [nss_cmd_getby_dp_callback] (0x0040): Unable to get information from Data Provider
Error: 3, 5, (null)
Will try to return what we have in cache
(Fri Jan 20 08:44:28 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/xxx.xxx.uchicago.edu/@apache at activedirectory.uchicago.edu<http://xxx.xxx.uchicago.edu/@apache@activedirectory.uchicago.edu>]
(Fri Jan 20 08:44:28 2017) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [apache at activedirectory.uchicago.edu<mailto:apache at activedirectory.uchicago.edu>]

On Jan 20, 2017, at 11:16 AM, Sullivan, Daniel [CRI] <dsullivan2 at bsd.uchicago.edu<mailto:dsullivan2 at bsd.uchicago.edu>> wrote:

Sorry I didn’t realize you might want all sssd logs… Working on it.

Dan

On Jan 20, 2017, at 10:27 AM, Sumit Bose <sbose at redhat.com<mailto:sbose at redhat.com>> wrote:

On Fri, Jan 20, 2017 at 03:41:46PM +0000, Sullivan, Daniel [CRI] wrote:
Hi,

I have some more information on this issue.  I’m tracing it down through the slapd logs and  I am continuing to struggle; I was hoping that somebody could possibly help me provided this additional information.

On the domain logs (on the DC), I see an ldap_search_ext operation 155 with a timeout of 60:

(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-xxx))][cn=Default Trust View,cn=views,cn=accounts,dc=xxx,dc=xxx,dc=uchicago,dc=edu].
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 155
(Fri Jan 20 08:42:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_add] (0x2000): New operation 155 timeout 60

Then, on the slapd log for the server, I see the incoming request.  Based on the result, it looks like the request completes successfully within 1 second:

[20/Jan/2017:08:42:35.179890746 -0600] conn=1518 op=31 SRCH base="cn=Default Trust View,cn=views,cn=accounts,dc=xxx,dc=xxx,dc=uchicago,dc=edu" scope=2 filter="(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-xxx))" attrs=ALL
[20/Jan/2017:08:42:35.683485674 -0600] conn=1518 op=31 RESULT err=0 tag=101 nentries=0 etime=1 notes=U

Then, subsequently, the domain log (on the DC), I see the same operation 155 timeout (expectedly almost a minute later).

So it looks like ns-ldap send the response but it never reached SSSD in
time. Can you send what it happening in the SSSD logs between 08:42:34
and 08:43:34 (if you prefer you can send it to me directly). Maybe there
is an operation which blocks SSSD for too long so that it returns too
late to the main loop to process the response?

bye,
Sumit

(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_timeout] (0x1000): Issuing timeout for 155
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_op_destructor] (0x1000): Abandoning operation 155
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_get_ad_override_done] (0x0040): ipa_get_ad_override request failed.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_initgr_get_overrides_override_done] (0x0040): IPA override lookup failed: 110
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_id_get_groups_overrides_done] (0x0040): IPA resolve user groups overrides failed [110].
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [be_mark_dom_offline] (0x1000): Marking subdomain activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/> offline
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [be_mark_subdom_offline] (0x1000): Marking subdomain activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/> as inactive
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [110]: Connection timed out.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [110]: Connection timed out.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request?
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_done] (0x0400): DP Request [Account #4292]: Request handler finished [0]: Success
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [_dp_req_recv] (0x0400): DP Request [Account #4292]: Receiving request data.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #4292]: Finished. Success.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_reply_std] (0x1000): DP Request [Account #4292]: Returning [Success]: 0,110,Success
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:1::activedirectory.uchicago.edu<http://activedirectory.uchicago.edu/>:name=userame at domain.uchicago.edu<mailto:name=userame at domain.uchicago.edu>] from reply table
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_destructor] (0x0400): DP Request [Account #4292]: Request removed.
(Fri Jan 20 08:43:34 2017) [sssd[be[xxx.xxx.uchicago.edu<http://xxx.xxx.uchicago.edu/>]]] [dp_req_destructor] (0x0400): Number of active DP request: 1

It seems like whatever problem I have is a communication issue between sssd on the domain controller, and ns-slapd.  I’m starting to venture down the road of doing trace/packet level debug logging on the LDAP server; this could be very time consuming and frustrating (I already have it enabled, I am starting to manipulate the log settings to yield potentially valuable data), I’m hoping that somebody might be able to provide some insight based on the information above; I can definitely lookup the user on both domain controllers & both IPA servers only use themselves for IPA servers.  Thank you so much for reading and for your help.

Dan

On Jan 19, 2017, at 4:15 PM, Sullivan, Daniel [CRI] <dsullivan2 at bsd.uchicago.edu<mailto:dsullivan2 at bsd.uchicago.edu>> wrote:

Hi,

I’ve received incredibly good support from this mailing list previously; I am hoping that somebody can help me succeed in my ongoing efforts.  I have spent a few days on this at this point and I can’t seem to figure it out how to address this issue.  On my DCs I am seeing excessive ldap_search_ext and sdap_get_generic_ext_recv timeouts created solely by the invocation of the ‘id’ command on sssd clients.  This problem seems to present itself only when I parallelize lookups for an ‘uncached’ user (i.e. I have never performed an initial lookup).  Individual arbitrary one-off lookups for a single uncached user on a single system almost always work fine.  This leads me to believe this is a performance tuning issue.

We operate in an academic research computing unit (i.e. we have an HPC cluster), and I need the ability to lookup the same user in parallel (using the id command) across a relatively large number of systems, for example to spawn jobs that require large amounts of CPU cores and/or memory.  Right now I am doing about 50 parallel lookups for the same user to induce this problem.

Here is some background information:

1) I have read Jakub's “Anatomy of an SSSD Lookup” as well as “Performance Tuning of SSSD for large IPA-AD deployments”, as well as implemented recommendations from the performance tuning doc, including moving the sssd cache to tmpfs.
2) We are on ipa-server 4.4.0-14.el7_3.4 using a trusted AD domain; all of our consumed users and groups are in the AD trusted domain.  We have two domain controllers; each is a RHEL 7.3 VM with 6 GB of memory.  Almost all (if not all) of our clients are running at least sssd 1.14, and are all RHEL 6/7.  Neither DC is swapping, and both have 2 CPUs.
3) I have tuned SSSD clients on the DCs and all clients to include these options (the problem persists):
a) ldap_opt_timeout = 60
b) ldap_search_timeout = 60
4) On both DCs, I can clear the SSSD cache, and lookup all 2000 or so users in my environment with 40 concurrent lookups occurring locally on each DC (using UNIX job control).  I can process all 2000 lookups in this manner without any failures (on either DC), and have ‘pre-populated’ the SSSD cache on both DC’s by doing this.
6) I have made no additional performance tuning changes other than what has been described.

Would anybody be able to advise on any potential tuning that would be required (presumably on the DCs), to facilitate 50 parallel lookups without experiencing sdap_get_generic_ext_recv or  ldap_search_ext  timeouts?  Should I be able to do this sort of thing with relative ease?  I was hoping this would be the sort of thing that would just work, but based on my relatively extensive testing it doesn’t.  Any advice anybody could provide would be greatly appreciated.

Thank you,

Dan Sullivan

--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project