sssd_ssh.log
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [get_client_cred] (0x4000): Client creds: euid[2063] egid[2080] pid[4353]. (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55d51e299aa0][18] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ssh_protocol_parse_request] (0x0400): Requested domain [<ALL>] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ssh_cmd_get_user_pubkeys] (0x0400): Requesting SSH user public keys for [user] from [<ALL>] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_set_plugin] (0x2000): CR #2: Setting "User by name" plugin (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_send] (0x0400): CR #2: New request 'User by name' (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_process_input] (0x0400): CR #2: Parsing input name [user] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'user' matched without domain, user is user (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_set_name] (0x0400): CR #2: Setting name [user] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_select_domains] (0x0400): CR #2: Performing a multi-domain search (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_domains] (0x0400): CR #2: Search will check the cache and check the data provider (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain example.com type POSIX is valid (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_set_domain] (0x0400): CR #2: Using domain [example.com] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [example.com] rules (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #2: Looking up user@example.com (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [user@example.com] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/example.com/user@example.com] (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #2: [user@example.com] is not present in negative cache (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #2: Looking up [user@example.com] in cache (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55d51e2a6740
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55d51e2a6800
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Running timer event 0x55d51e2a6740 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Destroying timer event 0x55d51e2a6800 "ltdb_timeout"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Ending timer event 0x55d51e2a6740 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55d51e29e220
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55d51e29e2e0
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Running timer event 0x55d51e29e220 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Destroying timer event 0x55d51e29e2e0 "ltdb_timeout"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Ending timer event 0x55d51e29e220 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #2: Returning [user@example.com] from cache (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_ncache_filter] (0x0400): CR #2: This request type does not support filtering result by negative cache (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_create_and_add_result] (0x0400): CR #2: Found 1 entries in domain example.com (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_done] (0x0400): CR #2: Finished: Success (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55d51e2a9970
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55d51e2a9a30
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Running timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Destroying timer event 0x55d51e2a9a30 "ltdb_timeout"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Ending timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55d51e2a9970
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55d51e2a9a30
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Running timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Destroying timer event 0x55d51e2a9a30 "ltdb_timeout"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Ending timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55d51e2a9970
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55d51e2a9a30
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Running timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Destroying timer event 0x55d51e2a9a30 "ltdb_timeout"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ldb] (0x4000): Ending timer event 0x55d51e2a9970 "ltdb_callback"
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [ssh_protocol_done] (0x4000): Sending reply: success (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! (Fri Feb 28 12:14:23 2020) [sssd[ssh]] [client_close_fn] (0x2000): Terminated client [0x55d51e299aa0][18]
sssd_example.com.log (same request, just a little later so I could get clean output)
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x55905bec2f60 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): Dispatching. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x5][BE_REQ_SERVICES][name=ntp] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Account #337]: New request. Flags [0x0001]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [services_get_send] (0x1000): Preparing to search for services with filter [(&(cn=ntp)(ipServiceProtocol=udp)(objectclass=ipService))] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_next_base] (0x0400): Searching for services with base [cn=accounts,dc=example,dc=com] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_print_server] (0x2000): Searching 172.27.16.5:389 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=udp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 24 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 24 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 24 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): Search services with filter: (&(objectclass=service)(&(serviceProtocol=udp)(|(nameAlias=ntp)(name=ntp)))) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55905bee29a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55905befc3a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Running timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Destroying timer event 0x55905befc3a0 "ltdb_timeout"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Ending timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): No such entry (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Account #337]: Request handler finished [0]: Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #337]: Receiving request data. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #337]: Finished. Success. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #337]: Returning [Success]: 0,0,Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:5:udp:example.com:name=ntp] from reply table (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #337]: Request removed. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[(nil)], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x55905bec2f60 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): Dispatching. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x5][BE_REQ_SERVICES][name=ntp] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Account #338]: New request. Flags [0x0001]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [services_get_send] (0x1000): Preparing to search for services with filter [(&(cn=ntp)(ipServiceProtocol=tcp)(objectclass=ipService))] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_next_base] (0x0400): Searching for services with base [cn=accounts,dc=example,dc=com] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_print_server] (0x2000): Searching 172.27.16.5:389 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=tcp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 25 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 25 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 25 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): Search services with filter: (&(objectclass=service)(&(serviceProtocol=tcp)(|(nameAlias=ntp)(name=ntp)))) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55905bee29a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55905befc3a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Running timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Destroying timer event 0x55905befc3a0 "ltdb_timeout"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Ending timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): No such entry (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Account #338]: Request handler finished [0]: Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #338]: Receiving request data. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #338]: Finished. Success. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #338]: Returning [Success]: 0,0,Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:5:tcp:example.com:name=ntp] from reply table (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #338]: Request removed. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[(nil)], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x55905bec2f60 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): Dispatching. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x5][BE_REQ_SERVICES][name=ntp] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Account #339]: New request. Flags [0x0001]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [services_get_send] (0x1000): Preparing to search for services with filter [(&(cn=ntp)(ipServiceProtocol=dccp)(objectclass=ipService))] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_next_base] (0x0400): Searching for services with base [cn=accounts,dc=example,dc=com] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_print_server] (0x2000): Searching 172.27.16.5:389 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=dccp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 26 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 26 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 26 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=tcp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 25 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 25 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 25 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): Search services with filter: (&(objectclass=service)(&(serviceProtocol=tcp)(|(nameAlias=ntp)(name=ntp)))) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55905bee29a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55905befc3a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Running timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Destroying timer event 0x55905befc3a0 "ltdb_timeout"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Ending timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): No such entry (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Account #338]: Request handler finished [0]: Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #338]: Receiving request data. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #338]: Finished. Success. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #338]: Returning [Success]: 0,0,Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:5:tcp:example.com:name=ntp] from reply table (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #338]: Request removed. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[(nil)], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x55905bec2f60 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): Dispatching. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x5][BE_REQ_SERVICES][name=ntp] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Account #339]: New request. Flags [0x0001]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [services_get_send] (0x1000): Preparing to search for services with filter [(&(cn=ntp)(ipServiceProtocol=dccp)(objectclass=ipService))] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_next_base] (0x0400): Searching for services with base [cn=accounts,dc=example,dc=com] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_print_server] (0x2000): Searching 172.27.16.5:389 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=dccp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 26 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 26 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 26 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): No such entry (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Account #340]: Request handler finished [0]: Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #340]: Receiving request data. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #340]: Finished. Success. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #340]: Returning [Success]: 0,0,Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:5:udplite:example.com:name=ntp] from reply table (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #340]: Request removed. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[(nil)], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x55905bec2f60 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_dispatch] (0x4000): Dispatching. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x5][BE_REQ_SERVICES][name=ntp] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Account #341]: New request. Flags [0x0001]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sss_domain_get_state] (0x1000): Domain example.com is Active (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [services_get_send] (0x1000): Preparing to search for services with filter [(&(cn=ntp)(ipServiceProtocol=sctp)(objectclass=ipService))] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_next_base] (0x0400): Searching for services with base [cn=accounts,dc=example,dc=com] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_print_server] (0x2000): Searching 172.27.16.5:389 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ntp)(ipServiceProtocol=sctp)(objectclass=ipService))][cn=accounts,dc=example,dc=com]. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServicePort] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipServiceProtocol] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 28 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_add] (0x2000): New operation 28 timeout 6 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[0x55905bee7ba0], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_op_destructor] (0x2000): Operation 28 finished (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_get_services_process] (0x0400): Search for services, returned 0 results. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): Search services with filter: (&(objectclass=service)(&(serviceProtocol=sctp)(|(nameAlias=ntp)(name=ntp)))) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55905bee29a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55905befc3a0
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Running timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Destroying timer event 0x55905befc3a0 "ltdb_timeout"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): Ending timer event 0x55905bee29a0 "ltdb_callback"
(Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sysdb_search_services] (0x2000): No such entry (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Account #341]: Request handler finished [0]: Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Account #341]: Receiving request data. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #341]: Finished. Success. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #341]: Returning [Success]: 0,0,Success (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:5:sctp:example.com:name=ntp] from reply table (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Account #341]: Request removed. (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x55905beef580], connected[1], ops[(nil)], ldap[0x55905bed38d0] (Fri Feb 28 12:28:00 2020) [sssd[be[example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list