[SSSD-users] timeout and offline mode behaviour

Joschi Brauchle joschi.brauchle at tum.de
Tue Jun 3 06:25:19 UTC 2014


On 06/02/2014 05:39 PM, Simo Sorce wrote:
> On Mon, 2014-06-02 at 10:34 +0200, Joschi Brauchle wrote:
>> These are some of the details:
>> 1) The LDAP server has a local 192.168.x.x IP, which is resolvable globally.
>
> IPs in the 129.168 are not resolvable globally, they are private
> addresses and routing is not allowed outside private networks.

What I meant is that the DNS hostname of the LDAP server 
'gemini.lnt.ei.tum.de' is globally resolvable to its private 
'192.168.109.3' IP address. Unfortunately, this DNS setup cannot be 
changed..

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 am currently NOT connected to my home '192.168.109.0/24' network, but 
this is my current network config:
----------------------------
# ifconfig
wlan0     Link encap:Ethernet  HWaddr ...
           inet addr:192.168.1.11  Bcast:192.168.1.255  Mask:255.255.255.0
# route
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use 
Iface
default         SL2141I.home    0.0.0.0         UG    0      0        0 
wlan0
192.168.1.0     *               255.255.255.0   U     9      0        0 
wlan0
----------------------------

Pinging the LDAP server 'gemini.lnt.ei.tum.de' results in:
----------------------------
# ping gemini.lnt.ei.tum.de
PING gemini.lnt.ei.tum.de (192.168.109.3) 56(84) bytes of data.
 From 62.53.2.254 icmp_seq=1 Destination Net Unreachable
----------------------------

So why does the LDAP connection not terminate immediately with the same 
'destination net unreachable' status but time out instead?

Best regards,
Joschi Brauchle

-------------- 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/20140603/8916fb93/attachment-0001.p7s>


More information about the sssd-users mailing list