On Wed, Sep 19, 2012 at 08:43:48AM -0700, Caio James wrote:
On Sep 18, 2012, at 12:51 PM, Jakub Hrozek <jhrozek(a)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@default]
(Wed Sep 19 09:51:04 2012) [sssd[pam]] [sss_dp_issue_request] (0x0400): Identical request
in progress: [0x4175f0:3:apacbi@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..