#729 Async resolver unschedules timeout watcher too soon
Closed: Fixed None Opened 10 years ago by 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.


Fields changed

status: new => assigned

Fixed by:
- aa5e100
- 3241a0b

coverity: =>
resolution: => fixed
status: assigned => closed

Fields changed

rhbz: => 0

Metadata Update from @sgallagh:
- Issue assigned to sgallagh
- Issue set to the milestone: SSSD 1.5.0

4 years ago

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/1771

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Login to comment on this ticket.

Metadata