ehlo,
Simo Did you have a special reason for changing connection handling in commit https://git.fedorahosted.org/cgit/sssd.git/commit/?id=e05d3f5872263aadfbc2f6...
Because with such change it takes mugh longer unit sssd go into offline mode. I added few debug messages into sssd_async_connect_done. But most important is time of operations.
old behaviour with TEVENT_FD_READ | TEVENT_FD_WRITE --------------------------------------------------- (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ibm-x3650m4-01-vm-07.example.com' (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [21] for the connection. (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Creating request (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Before connect (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): After connect ret:-1 (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Calling tevent_add_fd TEVENT_FD_READ | TEVENT_FD_WRITE (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): Before connect (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): After connect ret:-1 errno:113 (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): connect failed [113][No route to host]. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_socket_state_destructor] (0x0400): closing socket [21] (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [get_port_status] (0x1000): Port status of port 636 for server 'ibm-x3650m4-01-vm-07.example.com' is 'not working' (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0020): No available servers for service 'LDAP' (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error])
current behaviour with TEVENT_FD_WRITE -------------------------------------- (Sat Jun 18 12:04:27 2016) [sssd[be[LDAP]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out (Sat Jun 18 12:04:27 2016) [sssd[be[LDAP]]] [sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ibm-x3650m4-01-vm-07.example.com' (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Creating request (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Before connect (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): After connect ret:-1 (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Calling tevent_add_fd (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sssd_async_connect_timeout] (0x0100): The connection timed out (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000): Trace: sh[0xfe49dc0], connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0], release_memory[0] (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [get_port_status] (0x1000): Port status of port 636 for server 'ibm-x3650m4-01-vm-07.example.com' is 'not working' (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0020): No available servers for service 'LDAP' (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error])
If you did not have a special reason for this change then I would appreciate if we could change it back.
Two patches attached.
LS
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
Simo.
On Sat, 2016-06-18 at 20:02 +0200, Lukas Slebodnik wrote:
ehlo,
Simo Did you have a special reason for changing connection handling in commit https://git.fedorahosted.org/cgit/sssd.git/commit/?id=e05d3f5872263aadfbc2f6...
Because with such change it takes mugh longer unit sssd go into offline mode. I added few debug messages into sssd_async_connect_done. But most important is time of operations.
old behaviour with TEVENT_FD_READ | TEVENT_FD_WRITE
(Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ibm-x3650m4-01-vm-07.example.com' (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [21] for the connection. (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Creating request (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Before connect (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): After connect ret:-1 (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Calling tevent_add_fd TEVENT_FD_READ | TEVENT_FD_WRITE (Sat Jun 18 11:47:03 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): Before connect (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): After connect ret:-1 errno:113 (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_connect_done] (0x0020): connect failed [113][No route to host]. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sssd_async_socket_state_destructor] (0x0400): closing socket [21] (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [113]: No route to host. (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [get_port_status] (0x1000): Port status of port 636 for server 'ibm-x3650m4-01-vm-07.example.com' is 'not working' (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0020): No available servers for service 'LDAP' (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sat Jun 18 11:47:04 2016) [sssd[be[LDAP]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error])
current behaviour with TEVENT_FD_WRITE
(Sat Jun 18 12:04:27 2016) [sssd[be[LDAP]]] [generic_ext_search_handler] (0x0040): sdap_get_generic_ext_recv failed [110]: Connection timed out (Sat Jun 18 12:04:27 2016) [sssd[be[LDAP]]] [sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ibm-x3650m4-01-vm-07.example.com' (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Creating request (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Before connect (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): After connect ret:-1 (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_connect_send] (0x0020): Calling tevent_add_fd (Sat Jun 18 12:04:28 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sssd_async_connect_timeout] (0x0100): The connection timed out (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [110]: Connection timed out. (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000): Trace: sh[0xfe49dc0], connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0], release_memory[0] (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [get_port_status] (0x1000): Port status of port 636 for server 'ibm-x3650m4-01-vm-07.example.com' is 'not working' (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [fo_resolve_service_send] (0x0020): No available servers for service 'LDAP' (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Sat Jun 18 12:04:34 2016) [sssd[be[LDAP]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error])
If you did not have a special reason for this change then I would appreciate if we could change it back.
Two patches attached.
LS
On (19/06/16 15:27), Simo Sorce wrote:
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
Yes, only the timeout kick in It might be caused by using DROP instead of REJECT in firewall. But users use DROP very often as well. But I'm not sure.
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
I added comment; similar as in commit message.
LS
On Mon, 2016-06-20 at 11:04 +0200, Lukas Slebodnik wrote:
On (19/06/16 15:27), Simo Sorce wrote:
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
Yes, only the timeout kick in It might be caused by using DROP instead of REJECT in firewall. But users use DROP very often as well. But I'm not sure.
If you had drop then I would expect you always to have to wait 6 seconds, the only case I can see happening here is that on a RST the epoll actually returns a readable event instead of a writable one.
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
I added comment; similar as in commit message.
Both commits look good to me.
Simo.
On (20/06/16 08:49), Simo Sorce wrote:
On Mon, 2016-06-20 at 11:04 +0200, Lukas Slebodnik wrote:
On (19/06/16 15:27), Simo Sorce wrote:
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
Yes, only the timeout kick in It might be caused by using DROP instead of REJECT in firewall. But users use DROP very often as well. But I'm not sure.
If you had drop then I would expect you always to have to wait 6 seconds, the only case I can see happening here is that on a RST the epoll actually returns a readable event instead of a writable one.
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
I added comment; similar as in commit message.
Both commits look good to me.
Are there any other comments form other developers?
LS
On Tue, Jun 28, 2016 at 12:48:04PM +0200, Lukas Slebodnik wrote:
On (20/06/16 08:49), Simo Sorce wrote:
On Mon, 2016-06-20 at 11:04 +0200, Lukas Slebodnik wrote:
On (19/06/16 15:27), Simo Sorce wrote:
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
Yes, only the timeout kick in It might be caused by using DROP instead of REJECT in firewall. But users use DROP very often as well. But I'm not sure.
If you had drop then I would expect you always to have to wait 6 seconds, the only case I can see happening here is that on a RST the epoll actually returns a readable event instead of a writable one.
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
I added comment; similar as in commit message.
Both commits look good to me.
Are there any other comments form other developers?
Please push them (I didn't do any tests, but I trust you did).
On (28/06/16 17:22), Jakub Hrozek wrote:
On Tue, Jun 28, 2016 at 12:48:04PM +0200, Lukas Slebodnik wrote:
On (20/06/16 08:49), Simo Sorce wrote:
On Mon, 2016-06-20 at 11:04 +0200, Lukas Slebodnik wrote:
On (19/06/16 15:27), Simo Sorce wrote:
As the commit message says, nothing more. Isn't it right to wait for 6 seconds as the timeout says ? Can you add debug to see what errno is returned (if any) ? Or does the code never trigger and only the timeout kick in ?
Yes, only the timeout kick in It might be caused by using DROP instead of REJECT in firewall. But users use DROP very often as well. But I'm not sure.
If you had drop then I would expect you always to have to wait 6 seconds, the only case I can see happening here is that on a RST the epoll actually returns a readable event instead of a writable one.
We can revert that change in tevent flags if they cause a regression, but I want a comment in the code that the connect() man page is misleading if that's the case.
I added comment; similar as in commit message.
Both commits look good to me.
Are there any other comments form other developers?
Please push them (I didn't do any tests, but I trust you did).
master: * bdadcaf271818e88e56e86c2bd90663a08fd9721 * 3108e0cce47ee168b86ac0de1deccee7e7f09119
LS
sssd-devel@lists.fedorahosted.org
-
Jakub Hrozek -
Lukas Slebodnik -
Simo Sorce