Async resolver unschedules timeout watcher too soon #1771

sssd-bot · 2020-05-02T12:15:42Z

Cloned from Pagure issue: https://pagure.io/SSSD/sssd/issue/729

Created at 2010-12-14 15:52:19 by sgallagh
Closed as Fixed
Assigned to sgallagh

(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [be_pam_handler] (4): Got request with the following data
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): domain: example.com
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): user: sgallagh
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): tty: :0.0
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): ruser:
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): rhost:
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): authtok type: 1
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): authtok size: 17
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): newauthtok type: 0
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): newauthtok size: 0
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): priv: 0
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [pam_print_data] (4): cli_pid: 6368
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x3034a90

(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x3b14e10

(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [ldb] (9): tevent: Destroying timer event 0x3b14e10 "ltdb_timeout"

(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [ldb] (9): tevent: Ending timer event 0x3034a90 "ltdb_callback"

(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [krb5_get_simple_upn] (9): Using simple UPN [sgallagh@EXAMPLE.COM].
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [check_if_ccache_file_is_used] (9): User [13041] is still active, reusing ccache file [/tmp/krb5cc_13041_NXf2lD].
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [check_for_valid_tgt] (7): TGT end time [1292365688].
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [check_for_valid_tgt] (3): TGT is valid.
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [krb5_auth_send] (9): Ccache_file is [FILE:/tmp/krb5cc_13041_NXf2lD] and is  active and TGT is  valid.
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [get_server_status] (7): Status of server 'kerberos.example.com' is 'name not resolved'
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [get_port_status] (7): Port status of port 0 for server 'kerberos.example.com' is 'neutral'
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [get_server_status] (7): Status of server 'kerberos.example.com' is 'name not resolved'
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [resolv_gethostbyname_send] (4): Trying to resolve A record of 'kerberos.example.com'
(Tue Dec 14 09:42:21 2010) [sssd[be[example.com]]] [set_server_common_status] (4): Marking server 'kerberos.example.com' as 'resolving name'
(Tue Dec 14 09:42:22 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:26 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:27 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:31 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:31 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): dbus conn: 1C3F400
(Tue Dec 14 09:42:31 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): Dispatching.
(Tue Dec 14 09:42:31 2010) [sssd[be[example.com]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Dec 14 09:42:32 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:34 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:34 2010) [sssd[be[example.com]]] [resolv_gethostbyname_done] (4): Trying to resolve AAAA record of 'ldap.example.com'
(Tue Dec 14 09:42:37 2010) [sssd[be[example.com]]] [check_fd_timeouts] (9): Checking for DNS timeouts
(Tue Dec 14 09:42:37 2010) [sssd[be[example.com]]] [unschedule_timeout_watcher] (9): Unscheduling DNS timeout watcher
(Tue Dec 14 09:42:37 2010) [sssd[be[example.com]]] [resolv_gethostbyname_done] (4): Trying to resolve AAAA record of 'kerberos.example.com'
(Tue Dec 14 09:42:41 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): dbus conn: 1C3F400
(Tue Dec 14 09:42:41 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): Dispatching.
(Tue Dec 14 09:42:41 2010) [sssd[be[example.com]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Dec 14 09:42:51 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): dbus conn: 1C3F400
(Tue Dec 14 09:42:51 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): Dispatching.
(Tue Dec 14 09:42:51 2010) [sssd[be[example.com]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Dec 14 09:42:52 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): dbus conn: 1C3F400
(Tue Dec 14 09:42:52 2010) [sssd[be[example.com]]] [sbus_dispatch] (9): Dispatching.
(Tue Dec 14 09:42:52 2010) [sssd[be[example.com]]] [sbus_message_handler] (9): Received SBUS method [resetOffline]
(Tue Dec 14 09:42:52 2010) [sssd[be[example.com]]] [check_if_online] (8): Trying to go back online!
(Tue Dec 14 09:42:52 2010) [sssd[be[example.com]]] [check_if_online] (8): There is an online check already running.

It looks like if two requests come into the resolver, the first request can cancel the wait timer, leaving the second request waiting forever for a reply. This is likely to happen in situations like a screen unlock immediately after a resume or VPN drop, when both the LDAP server and Kerberos servers are being looked up to perform the auth.