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

Caio James rcj1 at me.com
Wed Sep 19 15:43:48 UTC 2012


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:

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
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:

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

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




Thanks for all of your help!

Caio


>> The user's connection is subsequently dropped, and they're not able to login until sssd is restarted. The sssd log doesn't seem to show any anomaly.
>> 
>> I've got sssd scheduled to restart twice per day with cron, but the traffic is increasing and users are now experiencing this more frequently.
>> 
>> I'm running Oracle Linux 6.3.
>> 
>>> [root at radvma29 ~]# sssd --version
>>> 1.8.0
>> 
>> 
>> My sssd.conf is below. Note that we do connect to an LDAP server insecurely. We're working with our IT team to fix this but it's a few months away:
>> 
> 
> I would urge you to fix this ASAP. Anyone can sniff your passwords in
> cleartext now. This is very dangerous.
> 
>>> [sssd]
>>> config_file_version = 2
>>> services = nss, pam
>>> debug_level = 5
>>> domains = default
>>> 
>>> [nss]
>>> 
>>> [pam]
>>> cache_credentials = true
>>> 
>>> [domain/default]
>>> ldap_auth_disable_tls_never_use_in_production = true
>>> access_provider = simple
>>> auth_provider = ldap
>>> chpass_provider = ldap
>>> cache_credentials = True
>>> krb5_realm = EXAMPLE.COM
>>> ldap_search_base = dc=mybusiness,dc=com
>>> id_provider = ldap
>>> ldap_uri = ldap://od.mybusiness.com/
>>> krb5_kdcip = kerberos.example.com
> 
> ^^ You can migrate to using krb5_server instead. It's basically just a new
> name for the same option. krb5_kdcip might be obsoleted at some point in
> the future.
> 
>>> ldap_tls_cacertdir = /etc/openldap/cacerts
>> 
>> Thank you for any direction that you can point me.
>> 
>> Caio
> _______________________________________________
> sssd-devel mailing list
> sssd-devel at lists.fedorahosted.org
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel



More information about the sssd-devel mailing list