[SSSD] Odd "Timer Expired" Errors causing SSH login drops

Jakub Hrozek jhrozek at redhat.com
Wed Sep 26 13:58:21 UTC 2012


On Wed, Sep 19, 2012 at 08:43:48AM -0700, Caio James wrote:
> 
> On Sep 18, 2012, at 12:51 PM, Jakub Hrozek <jhrozek at redhat.com> wrote:
> 
> > On Tue, Sep 18, 2012 at 07:37:30AM -0700, Caio James wrote:
> >> Greetings,
> >> 
> >> I'm running a file transfer server inside of my business with some decent traffic (but not what I would call heavy traffic).
> >> 
> >> Users use SFTP to transfer files. A couple of times per day, one or two of my users (not all of them) experience issues logging in. These users are local users, not LDAP. /var/log/secure shows the following:
> >> 
> >> 
> >>> Sep 18 08:17:04 radvma29 sshd[27378]: pam_unix(sshd:session): session opened for user wwbi by (uid=0)
> >>> Sep 18 08:27:04 radvma29 sshd[27378]: pam_sss(sshd:session): Request to sssd failed. Timer expired
> >> 
> > 
> > I think there's two issues really. I suspect one of them would be
> > PAM configuration.
> > 
> > Can you check which file is included from /etc/pam.d/sshd (it should be
> > password-auth) and then paste how the "session" stack looks like in that
> > file? I would expect that local users would not reach the pam_sss module at
> > all.
> 
> Here is the session stack from password-auth:
> 

I wonder if the following modification would help:

> session     optional      pam_keyinit.so revoke
> session     required      pam_limits.so
> session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
> session     required      pam_unix.so
--- add here ---
session sufficient pam_localuser.so
----------------
> session     optional      pam_sss.so
> 
> 
> > I suspect the second issue (that you're getting the "Timer expired" error)
> > would be a bug in the sssd_pam responder process. However, I don't have
> > enough information right now to debug the problem completely.
> > 
> > Can you put "debug_level" = 6 into the [pam] and [domain/default] sections,
> > restart the SSSD and paste the relevant contents (sanitized if needed)
> > of /var/log/sssd/sssd_default.log and/or /var/log/sssd/sssd_pam.log ?
> 
> Here are the entries from the two log files. I've snipped out what I think you're looking for in lieu of providing the entire log:
> 

Hmm, sorry, this log doesn't say much, it's only reporting that a client
connected. The only interesting part is that an identical request was
already in progress..I'll test that scenario locally.

Is there any way you could provide us with a bigger snippet of the log?

Also the recently released 1.9 version (and also the upcoming 1.8.5 version)
contains code that would mitigate an issue like this by terminating idle
connections.

Would you be interested in testing that patch if I built a test package
for you?

> sssd_pam.log
> (Wed Sep 19 09:51:04 2012) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4175f0:3:apacbi at default]
> (Wed Sep 19 09:51:04 2012) [sssd[pam]] [sss_dp_issue_request] (0x0400): Identical request in progress: [0x4175f0:3:apacbi at default]
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [accept_fd_handler] (0x0100): Client connected to privileged pipe!
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_cmd_close_session] (0x0100): entering pam_cmd_close_session
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_CLOSE_SESSION
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): domain: (null)
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): user: apacbi
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): ruser: (null)
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): rhost:bi09.asia.mybusiness.com
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 0
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Wed Sep 19 09:52:52 2012) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 21416
> 

The sssd_default.log also only reports that a user was requested but not
found in the directory.

> ssd_default.log
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [4099][1][name=apacbi]
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [get_server_status] (0x0100): Hostname resolution expired, resetting the server status of 'od.mybusiness.com'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'od.mybusiness.com' as 'name not resolved'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'od.mybusiness.com' in files
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'od.mybusiness.com' as 'resolving name'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'od.mybusiness.com' in files
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'od.mybusiness.com' in DNS
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [request_watch_destructor] (0x0400): Deleting request watch
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'od.mybusiness.com' as 'name resolved'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [be_resolve_server_done] (0x0200): Found address for server od.mybusiness.com: [17.128.115.44] TTL 300
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldap://od.mybusiness.com/'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [simple_bind_send] (0x0100): Executing simple bind as: (null)
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [simple_bind_done] (0x0200): Server returned no controls.
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [simple_bind_done] (0x0080): Bind result: Success(0), no errmsg set
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'od.mybusiness.com' as 'working'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'od.mybusiness.com' as 'working'
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=apple,dc=com]
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=apacbi)(objectclass=posixAccount))][dc=apple,dc=com].
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sysdb_search_user_by_name] (0x0400): No such entry
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory)
> (Wed Sep 19 09:51:04 2012) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
> 
> 
> 
> > Can you also check the number of files that the sssd_pam process has when
> > it misbehaves?
> > 
> > # lsof -p $(pidof sssd_pam) | wc -l
> > # lsof -p $(pidof sssd_pam) | grep pipes | wc -l
> 
> 
> While misbehaving:
> 
> # lsof -p $(pidof sssd_pam) | wc -l
> 117
> # lsof -p $(pidof sssd_pam) | grep pipes | wc -l
> 53
> 
> 
> After bouncing sssd:
> 
> # lsof -p $(pidof sssd_pam) | wc -l
> 66
> # lsof -p $(pidof sssd_pam) | grep pipes | wc -l
> 2

That shows we're definitely leaking a fd somewhere..



More information about the sssd-devel mailing list