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