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(a)example.com
(Fri Feb 28 12:14:23 2020) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #2: Checking
negative cache for [user(a)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(a)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(a)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(a)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