[SSSD-users] timeout and offline mode behaviour

Joschi Brauchle joschi.brauchle at tum.de
Thu Jun 5 09:05:55 UTC 2014


On 06/04/2014 09:41 AM, Joschi Brauchle wrote:
> On 06/03/2014 08:25 AM, Joschi Brauchle wrote:
>> On 06/02/2014 05:39 PM, Simo Sorce wrote:
>>
>> So I finally have a "debug_level = 9" log output from a lockup:
>> ----------------------------
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_message_handler]
>> (0x4000): Received SBUS method [getAccountInfo]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
>> (0x0100): Got request for [4097][1][idnumber=10011]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
>> (0x0100): Request processed. Returned 1,11,Fast reply - offline
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
>> (0x4000): beginning to connect
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [fo_resolve_service_send]
>> (0x0100): Trying to resolve service 'LDAP'
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [get_server_status]
>> (0x1000): Status of server 'gemini.lnt.ei.tum.de' is 'name resolved'
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [get_port_status]
>> (0x1000): Port status of port 636 for server 'gemini.lnt.ei.tum.de' is
>> 'not working'
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [get_port_status]
>> (0x0100): Reseting the status of port 636 for server
>> 'gemini.lnt.ei.tum.de'
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]]
>> [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to
>> 10 seconds
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [get_server_status]
>> (0x1000): Status of server 'gemini.lnt.ei.tum.de' is 'name resolved'
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]]
>> [be_resolve_server_process] (0x1000): Saving the first resolved server
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]]
>> [be_resolve_server_process] (0x0200): Found address for server
>> gemini.lnt.ei.tum.de: [192.168.109.3] TTL 7200
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sss_ldap_init_send]
>> (0x4000): Using file descriptor [21] for LDAP connection.
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sss_ldap_init_send]
>> (0x0400): Setting 6 seconds timeout for connecting
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> dbus conn: 18E8420
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> Dispatching.
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_message_handler]
>> (0x4000): Received SBUS method [getAccountInfo]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
>> (0x0100): Got request for [4097][1][name=brauchle]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
>> (0x4000): waiting for connection to complete
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> dbus conn: 18E8420
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> Dispatching.
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sbus_message_handler]
>> (0x4000): Received SBUS method [getAccountInfo]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
>> (0x0100): Got request for [4097][1][idnumber=10011]
>> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
>> (0x4000): waiting for connection to complete
>> (Tue Jun  3 08:16:47 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> dbus conn: 18BFD50
>> (Tue Jun  3 08:16:47 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
>> Dispatching.
>> (Tue Jun  3 08:16:47 2014) [sssd[be[default]]] [sbus_message_handler]
>> (0x4000): Received SBUS method [ping]
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]]
>> [sdap_async_sys_connect_timeout] (0x0100): The LDAP connection timed out
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]]
>> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect
>> request failed.
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_sys_connect_done]
>> (0x0020): sdap_async_connect_call request failed.
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_handle_release]
>> (0x2000): Trace: sh[0x191fdb0], connected[0], ops[(nil)], ldap[(nil)],
>> destructor_lock[0], release_memory[0]
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [fo_set_port_status]
>> (0x0100): Marking port 636 of server 'gemini.lnt.ei.tum.de' as 'not
>> working'
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [fo_resolve_service_send]
>> (0x0100): Trying to resolve service 'LDAP'
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [get_server_status]
>> (0x1000): Status of server 'gemini.lnt.ei.tum.de' is 'name resolved'
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [get_port_status]
>> (0x1000): Port status of port 636 for server 'gemini.lnt.ei.tum.de' is
>> 'not working'
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [fo_resolve_service_send]
>> (0x0020): No available servers for service 'LDAP'
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [be_resolve_server_done]
>> (0x1000): Server resolution failed: 5
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
>> (0x0020): Failed to connect, going offline (5 [Input/output error])
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [be_mark_offline]
>> (0x2000): Going offline!
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [be_run_offline_cb]
>> (0x0080): Going offline. Running callbacks.
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
>> (0x4000): notify offline to op #1
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
>> (0x4000): notify offline to op #2
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [acctinfo_callback]
>> (0x0100): Request processed. Returned 1,11,Offline
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
>> (0x4000): notify offline to op #3
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [acctinfo_callback]
>> (0x0100): Request processed. Returned 1,11,Offline
>> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]]
>> [sdap_id_release_conn_data] (0x4000): releasing unused connection
>> ----------------------------
>>
>> As the logs are showing, the system was completely unresponsive for
>> about 5 seconds form 08:16:42 to 08:16:47 when the LDAP connection timed
>> out.

I did some further testing ...

As the logs above are showing, the *first* request to SSSD (which is 
triggering the reconnection trial) gets answered right away in offline mode:
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
 >> (0x0100): Got request for [4097][1][idnumber=10011]
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
 >> (0x0100): Request processed. Returned 1,11,Fast reply - offline
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
 >> (0x4000): beginning to connect
...

Only the *subsequent* requests that are received *while* SSSD is trying 
to (re-)connect to the LDAP server are queued until the connection times 
out (for at most 6 seconds). These pending requests are causing the 
system to block and annoy the user:

...
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
 >> (0x0100): Got request for [4097][1][name=brauchle]
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
 >> (0x4000): waiting for connection to complete
...
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [be_get_account_info]
 >> (0x0100): Got request for [4097][1][idnumber=10011]
 >> (Tue Jun  3 08:16:42 2014) [sssd[be[default]]] [sdap_id_op_connect_step]
 >> (0x4000): waiting for connection to complete
...

--> this is the time where the system is unresponsive <--

...
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
 >> (0x0020): Failed to connect, going offline (5 [Input/output error])
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [be_mark_offline]
 >> (0x2000): Going offline!
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [be_run_offline_cb]
 >> (0x0080): Going offline. Running callbacks.
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
 >> (0x4000): notify offline to op #1
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
 >> (0x4000): notify offline to op #2
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [acctinfo_callback]
 >> (0x0100): Request processed. Returned 1,11,Offline
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [sdap_id_op_connect_done]
 >> (0x4000): notify offline to op #3
 >> (Tue Jun  3 08:16:48 2014) [sssd[be[default]]] [acctinfo_callback]
 >> (0x0100): Request processed. Returned 1,11,Offline


So why not keep the "offline" flag set to "true" until the LDAP 
connection succeeds and only if so, go to online mode?

As the first request (triggering the reconnection) is answered from the 
cache anyway, I dont see the point why one needs to keep the subsequent 
ones pending until the connection is established successfully...

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4739 bytes
Desc: S/MIME Cryptographic Signature
URL: <https://lists.fedorahosted.org/pipermail/sssd-users/attachments/20140605/54788b3f/attachment.p7s>


More information about the sssd-users mailing list