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:
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@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
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@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(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel