[SSSD] Trying to get id proxy to work

Joshua C. Endries jce54 at cornell.edu
Fri Oct 19 14:20:49 UTC 2012


Sorry, this is pretty long, but hopefully it has some useful info in it...

First, I have SELinux in Permissive mode, so hopefully that isn't causing problems. It has been the whole time. That said, I haven't seen any logs from it either.

Well, I have no idea why, but getent is working now:

[root pam.d]# getent passwd -s sss jce54
jce54:*:1000:1000::/mnt/home/jce54:/bin/bash

This is after starting with no cache (I think). I normally run sssd like this since I'm testing:

# rm -f /var/lib/sss/db/* ; sssd -i -d 7

This is the output of a fresh startup when I run getent. Note there are still "errors":

(Fri Oct 19 09:08:41 2012) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [nss_cmd_getpwnam] (4): Requesting info for [jce54] from [<ALL>]
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (4): Requesting info for [jce54 at DEFAULT]
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [DEFAULT][4097][1][name=jce54]
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [be_get_account_info] (4): Got request for [4097][1][name=jce54]
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [get_pw_name] (7): Searching user by name (jce54)
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [get_pw_name] (7): User jce54 found: (jce54, 1000, 1000)
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
(Fri Oct 19 09:08:41 2012) [sssd[be[DEFAULT]]] [acctinfo_callback] (4): (Fri Oct 19 09:08:41 2012) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (0, 0, Success) from Data Provider
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (4): Requesting info for [jce54 at DEFAULT]
Request processed. Returned 0,0,Success
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (6): Returning info for user [jce54 at DEFAULT]
(Fri Oct 19 09:08:41 2012) [sssd[nss]] [client_recv] (5): Client disconnected!

I suppose these errors relate to sssd's internal database or the cache? Either way, it seems the "files" proxy works here and that's sufficient for sssd. I set my local password to be different from my Kerberos pasword so I can tell which is working. I can log in through sssd with my local password. Though this works, it might be because PAM is querying SSSD, that fails, and PAM continues on:

(Fri Oct 19 08:49:52 2012) [sssd[pam]] [accept_priv_fd_handler] (4): Client connected to privileged pipe!
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [sss_cmd_get_version] (5): Received client version [3].
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [sss_cmd_get_version] (5): Offered version [3].
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_cmd_acct_mgmt] (4): entering pam_cmd_acct_mgmt
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): domain: (null)
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): user: jce54
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): service: sshd
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): tty: ssh
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): ruser: (null)
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): rhost: desktop...
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): authtok type: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): authtok size: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): newauthtok type: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): newauthtok size: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): priv: 1
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): cli_pid: 11451
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [sss_dp_send_acct_req_create] (4): Sending request for [DEFAULT][3][1][name=jce54]
(Fri Oct 19 08:49:52 2012) [sssd[be[DEFAULT]]] [be_get_account_info] (4): Got request for [3][1][name=jce54]
(Fri Oct 19 08:49:52 2012) [sssd[be[DEFAULT]]] [acctinfo_callback] (4): Request processed. Returned 3,19,Initgroups call not supported
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [sss_dp_get_reply] (4): Got reply (3, 19, Initgroups call not supported) from Data Provider
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_check_user_dp_callback] (2): Unable to get information from Data Provider
Error: 3, 19, Initgroups call not supported
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_check_user_search] (4): Requesting info for [jce54 at DEFAULT]
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_check_user_search] (2): No matching domain found for [jce54], fail!
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_reply] (4): pam_reply get called.
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_reply] (4): blen: 8
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_cmd_open_session] (4): entering pam_cmd_open_session
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): command: PAM_OPEN_SESSION
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): domain: (null)
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): user: jce54
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): service: sshd
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): tty: ssh
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): ruser: (null)
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): rhost: desktop...
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): authtok type: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): authtok size: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): newauthtok type: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): newauthtok size: 0
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): priv: 1
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_print_data] (4): cli_pid: 11451
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_check_user_search] (4): Requesting info for [jce54 at DEFAULT]
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_check_user_search] (2): No matching domain found for [jce54], fail!
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_reply] (4): pam_reply get called.
(Fri Oct 19 08:49:52 2012) [sssd[pam]] [pam_reply] (4): blen: 8
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [nss_cmd_initgroups] (4): Requesting info for [jce54] from [<ALL>]
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [nss_cmd_initgroups_search] (4): Requesting info for [jce54 at DEFAULT]
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [DEFAULT][4099][1][name=jce54]
(Fri Oct 19 08:49:52 2012) [sssd[be[DEFAULT]]] [be_get_account_info] (4): Got request for [4099][1][name=jce54]
(Fri Oct 19 08:49:52 2012) [sssd[be[DEFAULT]]] [acctinfo_callback] (4): Request processed. Returned 3,19,Initgroups call not supported
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (3, 19, Initgroups call not supported) from Data Provider
(Fri Oct 19 08:49:52 2012) [sssd[nss]] [nss_cmd_initgroups_dp_callback] (2): Unable to get information from Data Provider
Error: 3, 19, Initgroups call not supported
Will try to return what we have in cache

I'm guessing that the "no matching domain" error has nothing to do with Kerberos and really means that, of all the domains configured in sssd.conf (of which I only have one: DEFAULT), the user jce54 wasn't found in any of them. Correct? If I had a domain FOO that did work, this wouldn't be there? Just a guess.

This suggests to me that SSH asked PAM, PAM asked SSSD (which failed), then checked shadow, and let me in. If I try with my Kerberos password, it doesn't let me in:

(Fri Oct 19 08:58:12 2012) [sssd[pam]] [accept_priv_fd_handler] (4): Client connected to privileged pipe!
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [sss_cmd_get_version] (5): Received client version [3].
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [sss_cmd_get_version] (5): Offered version [3].
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_cmd_authenticate] (4): entering pam_cmd_authenticate
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): domain: (null)
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): user: jce54
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): service: sshd
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): tty: ssh
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): ruser: (null)
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): rhost: desktop...
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): authtok type: 1
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): authtok size: 9
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): newauthtok type: 0
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): newauthtok size: 0
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): priv: 1
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_print_data] (4): cli_pid: 11583
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [sss_dp_send_acct_req_create] (4): Sending request for [DEFAULT][3][1][name=jce54]
(Fri Oct 19 08:58:12 2012) [sssd[be[DEFAULT]]] [be_get_account_info] (4): Got request for [3][1][name=jce54]
(Fri Oct 19 08:58:12 2012) [sssd[be[DEFAULT]]] [acctinfo_callback] (4): Request processed. Returned 3,19,Initgroups call not supported
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [sss_dp_get_reply] (4): Got reply (3, 19, Initgroups call not supported) from Data Provider
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_check_user_dp_callback] (2): Unable to get information from Data Provider
Error: 3, 19, Initgroups call not supported
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_check_user_search] (4): Requesting info for [jce54 at DEFAULT]
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_check_user_search] (2): No matching domain found for [jce54], fail!
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_reply] (4): pam_reply get called.
(Fri Oct 19 08:58:12 2012) [sssd[pam]] [pam_reply] (4): blen: 8

I find it interesting that the previous log, with my local password that lets me in, has PAM_ACCT_MGMT and PAM_OPEN_SESSION commands, which I suppose refers to PAM's account and session sections, yet this one only has PAM_AUTHENTICATE. This is probably because it hits the "sufficient" unix module first, before the sssd module, and therefore PAM_AUTHENTICATE is already satisfied... If this one did work, I would expect to see those other two commands after it, but it's just a guess.

SSH is set to UsePAM=yes but is using the default GSSAPI=no, in case that matters (I wouldn't think so with PAM). I don't see any Kerberos stuff in the sssd output, though, so it might be getting hung up on NSS still? Here's my PAM system-auth again. I removed LDAP and krb5 (even though they were commented out before):

auth        required      pam_env.so
auth        sufficient    pam_unix.so nullok try_first_pass
auth        requisite     pam_succeed_if.so uid >= 500 quiet
auth sufficient pam_sss.so use_first_pass
auth        required      pam_deny.so

account     required      pam_unix.so broken_shadow
account     sufficient    pam_succeed_if.so uid < 500 quiet
account [default=bad success=ok user_unknown=ignore] pam_sss.so
account     required      pam_permit.so

password    requisite     pam_cracklib.so try_first_pass retry=3
password    sufficient    pam_unix.so md5 shadow nullok try_first_pass use_authtok
password sufficient pam_sss.so use_authtok
password    required      pam_deny.so

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 sufficient pam_sss.so
session     required      pam_unix.so

I'm no PAM pro, but I think the auth section indicates that, with my Kerberos password, SSH talks to PAM, PAM checks against shadow which fails but that's OK since it's sufficient, then PAM asks SSSD which fails but that's OK since it's sufficient, then PAM checks deny and kicks me out.

If I change PAM to this:

account     required      pam_unix.so broken_shadow
account     sufficient    pam_succeed_if.so uid < 500 quiet
#account [default=bad success=ok user_unknown=ignore] pam_sss.so
account required pam_sss.so
account     required      pam_permit.so

Then using my local Unix password doesn't work anymore, which makes me wonder if sssd isn't talking to NSS correctly and that's preventing it from trying Kerberos at all. With this config, login doesn't work but getent still shows my account and I still get this in the log:

(Fri Oct 19 09:03:12 2012) [sssd[pam]] [pam_check_user_dp_callback] (2): Unable to get information from Data Provider
Error: 3, 19, Initgroups call not supported

I changed PAM account back the way it was. I think it's pretty irrelevant really, for what I'm trying to do, UNLESS it's preventing some other step from happening.

Hopefully something in here helps. Thanks again!

Josh


More information about the sssd-devel mailing list