Issue #628: Kerberos provider does not recover from timeout - sssd

SSSD / sssd

#628 Kerberos provider does not recover from timeout

Closed: Fixed None Opened 13 years ago by dpal.

Scenario:
Worked for some time over VPN and then stepped out for 10 min. Screen locked.
Come to unlock the screen and observe the delay. VPN is connected.

Here is the log:

(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=tempuser]

Those are local users that I have. I do not have a clue why they are getting any activity at all.
Is this cron? But what is it doing?


(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_OPEN_SESSION
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (myuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_CLOSE_SESSION
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (tempuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=tempuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=postfix]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=tempuser]
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (myuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (tempuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [3][1][name=dpal]
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [sdap_save_group_done] (2): Failed to save group devel [5]
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [sdap_save_groups_loop] (2): Failed to store group 0. Ignoring.


Hm this sounds alarming. Should we be worried???



(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success



Success even if failed to save???


Ok here comes my auth....



(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 1
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 10
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [check_for_valid_tgt] (3): TGT is valid.
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [get_port_status] (4): Reseting the status of port 0 for server 'xxx.yyy.com'
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_resolve_server_done] (4): Found address for server xxx.yyy..com: [A.B.C.D]
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [krb5_child_done] (1): child failed (110 [Connection timed out])


Really???


(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'xxx.yyy.com' as 'not working'


Ok it failed, may be the KDC is slow or something like. Fine...
But why it is trying the second time???



(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [get_port_status] (4): Reseting the status of port 0 for server 'xxx.yyy..com'
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [be_resolve_server_done] (4): Found address for server xxx.yyy..com: [A.B.C.D]
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): waitpid did not found a child with changed status.
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): child [18665] was terminated by signal [9].



And what is it doing for another 15 seconds!!!!???



(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [krb5_child_done] (1): child failed (110 [Connection timed out])
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'kerberos.corp.redhat.com' as 'not working'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (1): No available servers for service 'KERBEROS'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (1, 9, <NULL>) [Provider is Offline (Bad file descriptor)]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [9][redhat.com]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [9][redhat.com]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): child [18666] was terminated by signal [9].
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [0][redhat.com]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [3][1][name=dpal]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 1,11,Offline
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_SETCRED
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser: 
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost: 
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]

So several questions...
1) Why I do not see anything in the child log (I have debug level 1) Would be nice to have at least high level debug there.
2) Why it ties twice? Seems like failover is not working properly.
3) Why local users are scanned in some way by cron?

This is a pretty repeatable situation.

dpal commented 13 years ago

Fields changed

description: Scenario:
Worked for some time over VPN and then stepped out for 10 min. Screen locked.
Come to unlock the screen and observe the delay. VPN is connected.

Here is the log:
{{{
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=tempuser]

Those are local users that I have. I do not have a clue why they are getting any activity at all.
Is this cron? But what is it doing?

(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_OPEN_SESSION
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (myuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_CLOSE_SESSION
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: crond
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: cron
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18549
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (tempuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=tempuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=myuser]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=postfix]
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:01 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [1][1][name=tempuser]
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [sdap_get_initgr_user] (2): Expected one user entry and got 0
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 3,2,Init Groups Failed
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (myuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [users_get_delete] (2): User (tempuser) delete returned 2 (No such file or directory)
(Fri Sep 17 14:00:02 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [3][1][name=dpal]
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [sdap_save_group_done] (2): Failed to save group devel [5]
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [sdap_save_groups_loop] (2): Failed to store group 0. Ignoring.

Hm this sounds alarming. Should we be worried???

(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success

Success even if failed to save???

Ok here comes my auth....

(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 1
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 10
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [check_for_valid_tgt] (3): TGT is valid.
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [get_port_status] (4): Reseting the status of port 0 for server 'xxx.yyy.com'
(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [be_resolve_server_done] (4): Found address for server xxx.yyy..com: [A.B.C.D]
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [krb5_child_done] (1): child failed (110 [Connection timed out])

Really???

(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'xxx.yyy.com' as 'not working'

Ok it failed, may be the KDC is slow or something like. Fine...
But why it is trying the second time???

(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [get_port_status] (4): Reseting the status of port 0 for server 'xxx.yyy..com'
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [be_resolve_server_done] (4): Found address for server xxx.yyy..com: [A.B.C.D]
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): waitpid did not found a child with changed status.
(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): child [18665] was terminated by signal [9].

And what is it doing for another 15 seconds!!!!???

(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [krb5_child_done] (1): child failed (110 [Connection timed out])
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'kerberos.corp.redhat.com' as 'not working'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [fo_resolve_service_send] (1): No available servers for service 'KERBEROS'
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (1, 9, <NULL>) [Provider is Offline (Bad file descriptor)]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [9][redhat.com]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [9][redhat.com]
(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [child_sig_handler] (1): child [18666] was terminated by signal [9].
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sending result [0][redhat.com]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler_callback] (4): Sent result [0][redhat.com]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_get_account_info] (4): Got request for [3][1][name=dpal]
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 1,11,Offline
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Got request with the following data
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): command: PAM_SETCRED
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): domain: redhat.com
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): user: dpal
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): tty: :0.0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): ruser:
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): rhost:
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): authtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok type: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): newauthtok size: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): priv: 0
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [pam_print_data] (4): cli_pid: 18649
(Fri Sep 17 14:04:40 2010) [sssd[be[redhat.com]]] [be_pam_handler] (4): Sending result [0][redhat.com]

}}}

So several questions...
1) Why I do not see anything in the child log (I have debug level 1). Would be nice to have at least high level debug there.
2) Why it ties twice? Seems like failover is not working properly.
3) Why local users are scanned in some way by cron?

This is a pretty repeatable situation.

=> Scenario:
Worked for some time over VPN and then stepped out for 10 min. Screen locked.
Come to unlock the screen and observe the delay. VPN is connected.

Those are local users that I have. I do not have a clue why they are getting any activity at all.
Is this cron? But what is it doing?

Hm this sounds alarming. Should we be worried???

(Fri Sep 17 14:04:07 2010) [sssd[be[redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success

Success even if failed to save???

Ok here comes my auth....

Really???

(Fri Sep 17 14:04:23 2010) [sssd[be[redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'xxx.yyy.com' as 'not working'

Ok it failed, may be the KDC is slow or something like. Fine...
But why it is trying the second time???

And what is it doing for another 15 seconds!!!!???

}}}

This is a pretty repeatable situation.

sgallagh commented 13 years ago

Changing the subject.

It looks like what's actually happening here is that the KDC isn't responding within the krb5_auth_timeout for one reason or another (possibly faulty VPN software). However, the second call to krb5_child that should operate in offline mode to set up the credential cache appears to be failing.

It should be possible to reproduce this behavior by setting up a firewall rule to drop (not reject) packets coming into the KDC so that to the SSSD it will look like the KDC is timing out (DNS and LDAP should be left on so that it gets to the KDC rather than being declared offline earlier by one of those two)

component: SSSD => Kerberos Provider
priority: major => critical
summary: SSSD thinks that I am offline when I am online => Kerberos provider does not recover from timeout

dpal commented 13 years ago

Fields changed

milestone: NEEDS_TRIAGE => SSSD 1.5.0

dpal commented 13 years ago

Fields changed

owner: somebody => sgallagh

sbose commented 13 years ago

Fields changed

owner: sgallagh => sbose

sbose commented 13 years ago

comment to 1) This timeout is handled by the parent, which terminates the child it the timeout exceeded, but the child does not know the reason. So you only can have the high level log message in the parents log file:

(Fri Sep 17 14:04:39 2010) [sssd[be[redhat.com]]] [krb5_child_done] (1): child failed (110 [Connection timed out])

comment to 2) I think I've found the reason, see '[PATCH] Store krb5 auth context for other targets' on sssd-devel

If the fix in the patch works, I think we can close the ticket.

sgallagh commented 13 years ago

Fixed by 0b0a1e4

fixedin: => 1.5.0
resolution: => fixed
status: new => closed

dpal commented 12 years ago

Fields changed

rhbz: => 0

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

7 years ago

pbrezina commented 3 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/1670

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.

Metadata

Assignee

sbose

Tags

None

Blocking

None

Depending on

None

Priority

critical

Milestone

SSSD 1.5.0

type

defect

component

Kerberos Provider

version

1.2.1

selected

None

testsupdated

patch

None

rhbz

design_review

None

review

None

changelog

None

keywords

None

coverity

None

mark

None

blocking

None

design

None

sensitive

None

blockedby

None

feature_milestone

None

SSSD / sssd

Source Code

Documentation

#628 Kerberos provider does not recover from timeout Closed: Fixed None Opened 13 years ago by dpal.

Metadata

#628 Kerberos provider does not recover from timeout

Closed: Fixed None Opened 13 years ago by dpal.