Bug#541188: no login possible after some time (using ldap, krb5, ssh, login)
Nico Schottelius
Version: 1.0.1-5+lenny1
Severity: serious
After some time we get this message when trying to login to a debian node:
root@debian-host: ssh_exchange_identification: Connection closed by remote host
We have some clusters with debian running and about 30 nodes have this problem.
It makes no difference, if I try as root (= without ldap) or as a real user, if I use
password or public key auth.
If I go to the local console (i.e. tty1) and login as a NORMAL user, the whole authentication
works again.
Though, locally I CANNOT login as root, until I login as a normal user before.
After I logged into as a normal user, I can also ssh into the machine again.
It seems that pam has a bug that is triggered after some time, that "forgets" about the users:
-------------------------------
Aug 8 21:55:01 ikr3 /USR/SBIN/CRON[19476]: (root) CMD ([ -x /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ; [ "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 ; })
Aug 8 21:55:01 ikr3 CRON[19474]: (pam_krb5): none: pam_sm_setcred: entry (0x8004)
Aug 8 21:55:01 ikr3 CRON[19474]: (pam_krb5): none: pam_sm_setcred: exit (success)
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: pam_sm_setcred: entry (0x8002)
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: no context found, creating one
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: pam_sm_setcred: exit (failure)
Aug 8 22:00:01 ikr3 /USR/SBIN/CRON[19491]: (root) CMD (/usr/sbin/ntpdate time.ethz.ch > /dev/null)
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: pam_sm_setcred: entry (0x8004)
Aug 8 22:00:01 ikr3 CRON[19489]: (pam_krb5): none: pam_sm_setcred: exit (success)
Aug 8 22:00:33 ikr3 smartd[2728]: Device: /dev/hda, SMART Usage Attribute: 194 Temperature_Celsius changed from 196 to 203
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: pam_sm_setcred: entry (0x8002)
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: no context found, creating one
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: pam_sm_setcred: exit (failure)
Aug 8 22:05:01 ikr3 /USR/SBIN/CRON[19507]: (root) CMD ([ -x /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ; [ "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 ; })
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: pam_sm_setcred: entry (0x8004)
Aug 8 22:05:01 ikr3 CRON[19505]: (pam_krb5): none: pam_sm_setcred: exit (success)
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: pam_sm_setcred: entry (0x8002)
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: no context found, creating one
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: pam_sm_setcred: exit (failure)
Aug 8 22:15:01 ikr3 /USR/SBIN/CRON[19534]: (root) CMD ([ -x /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ; [ "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 ; })
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: pam_sm_setcred: entry (0x8004)
Aug 8 22:15:01 ikr3 CRON[19532]: (pam_krb5): none: pam_sm_setcred: exit (success)
Aug 8 22:17:01 ikr3 CRON[19538]: User not known to the underlying authentication module
Aug 8 22:25:01 ikr3 CRON[19561]: User not known to the underlying authentication module
Aug 8 22:30:34 ikr3 smartd[2728]: Device: /dev/hda, SMART Usage Attribute: 194 Temperature_Celsius changed from 203 to 196
Aug 8 22:35:01 ikr3 CRON[19588]: User not known to the underlying authentication module
Aug 8 22:39:40 ikr3 postfix/pickup[19602]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody
Aug 8 22:39:41 ikr3 postfix/master[2714]: warning: process /usr/lib/postfix/pickup pid 19602 exit status 1
Aug 8 22:39:41 ikr3 postfix/master[2714]: warning: /usr/lib/postfix/pickup: bad command startup -- throttling
Aug 8 22:40:41 ikr3 postfix/pickup[19604]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody
Aug 8 22:40:42 ikr3 postfix/master[2714]: warning: process /usr/lib/postfix/pickup pid 19604 exit status 1
Aug 8 22:40:42 ikr3 postfix/master[2714]: warning: /usr/lib/postfix/pickup: bad command startup -- throttling
Aug 8 22:41:42 ikr3 postfix/pickup[19609]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody
Aug 8 22:41:43 ikr3 postfix/master[2714]: warning: process /usr/lib/postfix/pickup pid 19609 exit status 1
Aug 8 22:41:43 ikr3 postfix/master[2714]: warning: /usr/lib/postfix/pickup: bad command startup -- throttling
Aug 8 22:42:43 ikr3 postfix/pickup[19614]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody
Aug 8 22:42:44 ikr3 postfix/master[2714]: warning: process /usr/lib/postfix/pickup pid 19614 exit status 1
-------------------------------
This continues, until I locally login again:
-----------------------------
Aug 12 11:38:00 ikr3 postfix/master[2714]: warning: process /usr/lib/postfix/pickup pid 9523 exit status 1
Aug 12 11:38:00 ikr3 postfix/master[2714]: warning: /usr/lib/postfix/pickup: bad command startup -- throttling
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: pam_sm_setcred: entry (0x8002)
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: no context found, creating one
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: pam_sm_setcred: exit (failure)
Aug 12 11:45:01 ikr3 /USR/SBIN/CRON[9557]: (root) CMD ([ -x /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ; [ "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1 1 ; })
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: pam_sm_setcred: entry (0x8004)
Aug 12 11:45:01 ikr3 CRON[9555]: (pam_krb5): none: pam_sm_setcred: exit (success)
-----------------------------
The auth.log says (excerpts):
Aug 8 22:00:01 ikr3 CRON[19489]: pam_unix(cron:session): session closed for user root
Aug 8 22:05:01 ikr3 CRON[19505]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 8 22:05:01 ikr3 CRON[19505]: pam_unix(cron:session): session closed for user root
Aug 8 22:15:01 ikr3 CRON[19532]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 8 22:15:01 ikr3 CRON[19532]: pam_unix(cron:session): session closed for user root
Aug 8 22:17:01 ikr3 CRON[19538]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 8 22:25:01 ikr3 CRON[19561]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 8 22:35:01 ikr3 CRON[19588]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 8 22:45:01 ikr3 CRON[19626]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 12 11:35:01 ikr3 CRON[9513]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 12 11:36:29 ikr3 sshd[9518]: fatal: Privilege separation user sshd does not exist
Aug 12 11:35:01 ikr3 CRON[9513]: pam_unix(cron:account): could not identify user (from getpwnam(root))
Aug 12 11:36:29 ikr3 sshd[9518]: fatal: Privilege separation user sshd does not exist
Aug 12 11:38:55 ikr3 login[2839]: (pam_krb5): none: pam_sm_authenticate: entry (0x0)
Aug 12 11:38:55 ikr3 login[2839]: (pam_krb5): nicosc: attempting authentication as nic...@D.ETHZ.CH
Aug 12 11:38:58 ikr3 login[2839]: (pam_krb5): nicosc: pam_sm_authenticate: exit (success)
Aug 12 11:38:58 ikr3 login[2839]: (pam_krb5): nicosc: pam_sm_setcred: entry (0x2)
Aug 12 11:38:58 ikr3 login[2839]: (pam_krb5): nicosc: initializing ticket cache FILE:/tmp/krb5cc_13270_wD32cC
Aug 12 11:38:58 ikr3 login[2839]: (pam_krb5): nicosc: pam_sm_setcred: exit (success)
Aug 12 11:38:58 ikr3 login[2839]: pam_env(login:session): Unable to open env file: /etc/default/locale: No such file or directory
Aug 12 11:38:58 ikr3 login[2839]: pam_unix(login:session): session opened for user nicosc by LOGIN(uid=0)
Aug 12 11:45:01 ikr3 CRON[9555]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 12 11:45:01 ikr3 CRON[9555]: pam_unix(cron:session): session closed for user root
Aug 12 11:45:02 ikr3 sshd[9558]: Accepted publickey for root from 129.132.130.136 port 38302 ssh2
Aug 12 11:45:02 ikr3 sshd[9558]: pam_env(sshd:setcred): Unable to open env file: /etc/default/locale: No such file or directory
Aug 12 11:45:02 ikr3 sshd[9558]: (pam_krb5): none: pam_sm_setcred: entry (0x2)
Aug 12 11:45:02 ikr3 sshd[9558]: (pam_krb5): none: no context found, creating one
Aug 12 11:45:02 ikr3 sshd[9558]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 12 11:45:02 ikr3 sshd[9558]: (pam_krb5): none: pam_sm_setcred: exit (failure)
Aug 12 11:45:02 ikr3 sshd[9558]: pam_unix(sshd:session): session opened for user root by (uid=0)
Aug 12 11:45:02 ikr3 sshd[9560]: pam_env(sshd:setcred): Unable to open env file: /etc/default/locale: No such file or directory
Aug 12 11:45:02 ikr3 sshd[9560]: (pam_krb5): none: pam_sm_setcred: entry (0x8)
Aug 12 11:45:02 ikr3 sshd[9560]: (pam_krb5): none: no context found, creating one
Aug 12 11:45:02 ikr3 sshd[9560]: (pam_krb5): none: ignoring low-UID user (0 < 1001)
Aug 12 11:45:02 ikr3 sshd[9560]: (pam_krb5): none: pam_sm_setcred: exit (failure)
/etc/pam.d file content:
common-account:
account required pam_unix.so broken_shadow
account sufficient pam_krb5.so minimum_uid=1001
common-auth:
auth sufficient pam_krb5.so try_first_pass minimum_uid=1001 debug
auth required pam_unix.so nullok_secure
(others are debian standard)
-- System Information:
Debian Release: 5.0.1
APT prefers stable
APT policy: (500, 'stable')
Architecture: amd64 (x86_64)
Kernel: Linux 2.6.26-2-amd64 (SMP w/4 CPU cores)
Locale: LANG=de_CH.UTF-8, LC_CTYPE=de_CH.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to de_CH.UTF-8)
Shell: /bin/sh linked to /bin/bash
-- no debconf information
--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Nico Schottelius
[15:46] ikn2:~% ssh root@ikr03 cat /etc/nsswitch.conf
# /etc/nsswitch.conf
#
# For ETH with LDAP
#
passwd: files ldap [UNAVAIL=return]
group: files ldap [UNAVAIL=return]
shadow: files
hosts: files dns
networks: files
protocols: db files
services: db files
ethers: db files
rpc: db files
netgroup: ldap
--
Currently moving *.schottelius.org to http://www.nico.schottelius.org/ ...
PGP: BFE4 C736 ABE5 406F 8F42 F7CF B8BE F92A 9885 188C
Nico Schottelius
> On Wed, Aug 12, 2009 at 12:15:03PM +0200, Nico Schottelius wrote:
> > It seems that pam has a bug that is triggered after some time, that
> > "forgets" about the users:
>
> configuration.
Well, if this is a configuration issue, why does it appear *after* some
amount of time and *not* directly?
> > Aug 8 22:39:40 ikr3 postfix/pickup[19602]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody
>
> If the user 'nobody' can't be resolved, you've broken things quite badly.
> Nothing to do with PAM.
>
> The 'nobody' user should *always* be a local user; this should resolve
> correctly even if the LDAP server is down. If you don't have the 'nobody'
> user in /etc/passwd, that's a configuration error. If you have the 'nobody'
> user in /etc/passwd but NSS fails to return the record because of some
That's the case here:
[16:58] ikn2:~% ssh root@host grep -e sshd -e nobody /etc/passwd
nobody:x:65534:65534:nobody:/nonexistent:/bin/sh
sshd:x:104:65534::/var/run/sshd:/usr/sbin/nologin
> credentials caching issue, then you have some NSS module bug or NSS
> configuration error. Either way, this is not a bug in pam.
Agreed, sorry, maybe the wrong package.
Can you reassign to libnss3-1d, please?
Greets,
Nico
Steve Langasek
> Steve Langasek [Wed, Aug 12, 2009 at 09:14:51AM -0700]:
> > On Wed, Aug 12, 2009 at 12:15:03PM +0200, Nico Schottelius wrote:
> > > It seems that pam has a bug that is triggered after some time, that
> > > "forgets" about the users:
> >
> > This is not a PAM bug, you appear to have a bug of some kind in your NSS
> > configuration.
> Well, if this is a configuration issue, why does it appear *after* some
> amount of time and *not* directly?
Most likely: your LDAP setup is broken and only allows the machine to query
the LDAP user directory when using GSSAPI authentication, while making no
provisions for the availability of persistent system-level Kerberos
credentials, so instead the LDAP lookups only work when something on the
system has "primed" the connection with a Kerberos TGT and stops working
when the tickets expire (by default, after 8 hours).
> > The 'nobody' user should *always* be a local user; this should resolve
> > correctly even if the LDAP server is down. If you don't have the 'nobody'
> > user in /etc/passwd, that's a configuration error. If you have the 'nobody'
> > user in /etc/passwd but NSS fails to return the record because of some
> That's the case here:
> [16:58] ikn2:~% ssh root@host grep -e sshd -e nobody /etc/passwd
> nobody:x:65534:65534:nobody:/nonexistent:/bin/sh
> sshd:x:104:65534::/var/run/sshd:/usr/sbin/nologin
Then your /etc/passwd is correct, but you have a broken NSS setup. This may
be a bug in libnss-ldap (if you're using the nss_ldap provided by that
Debian package), or it may be as simple as removing the atypical
'[UNAVAIL=return]' from the end of your lines in /etc/nsswitch.conf. But
either way, please consult debian-user or another suitable support forum;
I'm not going to further debug your configuration in this (misfiled) bug
report.
> > credentials caching issue, then you have some NSS module bug or NSS
> > configuration error. Either way, this is not a bug in pam.
> Agreed, sorry, maybe the wrong package.
> Can you reassign to libnss3-1d, please?
That's not the NSS we're talking about.
--
Steve Langasek Give me a lever long enough and a Free OS
Debian Developer to set it on, and I can move the world.
Ubuntu Developer http://www.debian.org/
slan...@ubuntu.com vor...@debian.org