[OpenAFS] pam_krb5 taking too long to authenticate
Kurt Seiffert
seiffert@indiana.edu
Tue, 25 Oct 2005 12:17:32 -0500
--Apple-Mail-27--7310083
Content-Transfer-Encoding: 7bit
Content-Type: text/plain;
charset=US-ASCII;
delsp=yes;
format=flowed
We have been having problems with the pam_krb5 module. It takes a
long time 20-30 seconds after entering your password for a prompt to
return. We having been able to figure out this problem yet. Here is a
sample of output from syslog during a login.
Of special interest is the 20 second jump at the following point:
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: preparing to place
> v4 credentials in '/tmp/tkt1529_Ic5472'
> Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: could not obtain
> initial v4 creds: 7 (Argument list too long)
Any advice on what is wrong or how to debug this further would be
helpful.
Thanks.
-KAS
> Oct 25 12:13:33 rfs2 sshd(pam_unix)[5472]: authentication failure;
> logname= uid=0 euid=0 tty=ssh ruser= rhost=156.56.13.2 user=seiffert
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: configured realm
> 'IU.EDU'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flags: forwardable
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: no ignore_afs
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: tokens
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: user_check
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: krb4_convert
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: warn
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: ticket lifetime:
> 36000
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: renewable
> lifetime: 36000
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: banner: Kerberos 5
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: ccache dir: /tmp
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: keytab: /etc/
> krb5.keytab
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: called to
> authenticate 'seiffert'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: authenticating
> 'seiffert@IU.EDU'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: trying previously-
> entered password for 'seiffert'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: authenticating
> 'seiffert@IU.EDU' to 'krbtgt/IU.EDU@IU.EDU'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]:
> krb5_get_init_creds_password(krbtgt/IU.EDU@IU.EDU) returned 0
> (Success)
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: got result 0
> (Success)
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: obtaining v4-
> compatible key
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: obtained des-cbc-
> crc v5 creds
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: converting v5
> creds to v4 creds (etype = 1)
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: conversion failed:
> -1765328377 (Server not found in Kerberos database)
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: obtaining initial
> v4 creds
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: converted
> principal to 'seiffert'[.]''@'IU.EDU'
> Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: preparing to place
> v4 credentials in '/tmp/tkt1529_Ic5472'
> Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: could not obtain
> initial v4 creds: 7 (Argument list too long)
> Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: error obtaining v4
> creds: 57 (Invalid slot)
> Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: authentication
> succeeds for 'seiffert' (seiffert@IU.EDU)
> Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: pam_authenticate
> returning 0 (Success)
> Oct 25 12:13:52 rfs2 sshd[5470]: Accepted keyboard-interactive/pam
> for seiffert from ::ffff:156.56.13.2 port 52071 ssh2
> Oct 25 12:13:52 rfs2 sshd(pam_unix)[5473]: session opened for user
> seiffert by (uid=0)
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: configured realm
> 'IU.EDU'
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flags: forwardable
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flag: no ignore_afs
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flag: user_check
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flag: krb4_convert
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flag: warn
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: ticket lifetime:
> 36000
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: renewable
> lifetime: 36000
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: banner: Kerberos 5
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: ccache dir: /tmp
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: keytab: /etc/
> krb5.keytab
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: no v5 creds for
> user 'seiffert', skipping session setup
> Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: pam_open_session
> returning 0 (Success)
> Oct 25 12:13:52 rfs2 pam_loginuid[5473]: set_loginuid failed
> opening loginuid
Kurt A. Seiffert | seiffert@indiana.edu
UITS Distributed Storage Services Group | C: 812-345-1892
Indiana University, Bloomington | W: 1 812-855-5089
--Apple-Mail-27--7310083
Content-Transfer-Encoding: quoted-printable
Content-Type: text/html;
charset=ISO-8859-1
<HTML><BODY style=3D"word-wrap: break-word; -khtml-nbsp-mode: space; =
-khtml-line-break: after-white-space; "><DIV>We have been having =
problems with the pam_krb5 module. It takes a long time 20-30 seconds =
after entering your password for a prompt to return. We having been able =
to figure out this problem yet. Here is a sample of output from syslog =
during a login.=A0</DIV><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><DIV>Of special interest is the =
20 second jump at the following point:</DIV><BLOCKQUOTE type=3D"cite"><DIV=
style=3D"">Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: preparing =
to place v4 credentials in '/tmp/tkt1529_Ic5472'</DIV><DIV style=3D"">Oct =
25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: could not obtain initial v4 =
creds: 7 (Argument list too long)</DIV></BLOCKQUOTE><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><DIV>Any advice on what is wrong =
or how to debug this further would be helpful.</DIV><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><DIV>Thanks.</DIV><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><DIV>-KAS<DIV><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><DIV><BR =
class=3D"khtml-block-placeholder"></DIV><BLOCKQUOTE type=3D"cite"><DIV>Oct=
25 12:13:33 rfs2 sshd(pam_unix)[5472]: authentication failure; logname=3D=
uid=3D0 euid=3D0 tty=3Dssh ruser=3D rhost=3D156.56.13.2=A0 =
user=3Dseiffert</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: configured realm 'IU.EDU'</DIV><DIV>Oct 25 12:13:33 rfs2 =
sshd[5472]: pam_krb5[5472]: flags: forwardable</DIV><DIV>Oct 25 12:13:33 =
rfs2 sshd[5472]: pam_krb5[5472]: flag: no ignore_afs</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: tokens</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: user_check</DIV><DIV>Oct =
25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: flag: =
krb4_convert</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: =
flag: warn</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: =
ticket lifetime: 36000</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: renewable lifetime: 36000</DIV><DIV>Oct 25 12:13:33 rfs2 =
sshd[5472]: pam_krb5[5472]: banner: Kerberos 5</DIV><DIV>Oct 25 12:13:33 =
rfs2 sshd[5472]: pam_krb5[5472]: ccache dir: /tmp</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: keytab: =
/etc/krb5.keytab</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: called to authenticate 'seiffert'</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: authenticating '<A =
href=3D"mailto:seiffert@IU.EDU">seiffert@IU.EDU</A>'</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: trying previously-entered =
password for 'seiffert'</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: authenticating '<A =
href=3D"mailto:seiffert@IU.EDU">seiffert@IU.EDU</A>' to 'krbtgt/<A =
href=3D"mailto:IU.EDU@IU.EDU">IU.EDU@IU.EDU</A>'</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: =
krb5_get_init_creds_password(krbtgt/<A =
href=3D"mailto:IU.EDU@IU.EDU">IU.EDU@IU.EDU</A>) returned 0 =
(Success)</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: got =
result 0 (Success)</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: obtaining v4-compatible key</DIV><DIV>Oct 25 12:13:33 =
rfs2 sshd[5472]: pam_krb5[5472]: obtained des-cbc-crc v5 =
creds</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: =
converting v5 creds to v4 creds (etype =3D 1)</DIV><DIV>Oct 25 12:13:33 =
rfs2 sshd[5472]: pam_krb5[5472]: conversion failed: -1765328377 (Server =
not found in Kerberos database)</DIV><DIV>Oct 25 12:13:33 rfs2 =
sshd[5472]: pam_krb5[5472]: obtaining initial v4 creds</DIV><DIV>Oct 25 =
12:13:33 rfs2 sshd[5472]: pam_krb5[5472]: converted principal to =
'seiffert'[.]''@'IU.EDU'</DIV><DIV>Oct 25 12:13:33 rfs2 sshd[5472]: =
pam_krb5[5472]: preparing to place v4 credentials in =
'/tmp/tkt1529_Ic5472'</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5472]: =
pam_krb5[5472]: could not obtain initial v4 creds: 7 (Argument list too =
long)</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: error =
obtaining v4 creds: 57 (Invalid slot)</DIV><DIV>Oct 25 12:13:52 rfs2 =
sshd[5472]: pam_krb5[5472]: authentication succeeds for 'seiffert' (<A =
href=3D"mailto:seiffert@IU.EDU">seiffert@IU.EDU</A>)</DIV><DIV>Oct 25 =
12:13:52 rfs2 sshd[5472]: pam_krb5[5472]: pam_authenticate returning 0 =
(Success)</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5470]: Accepted =
keyboard-interactive/pam for seiffert from ::ffff:156.56.13.2 port 52071 =
ssh2</DIV><DIV>Oct 25 12:13:52 rfs2 sshd(pam_unix)[5473]: session opened =
for user seiffert by (uid=3D0)</DIV><DIV>Oct 25 12:13:52 rfs2 =
sshd[5473]: pam_krb5[5473]: configured realm 'IU.EDU'</DIV><DIV>Oct 25 =
12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: flags: =
forwardable</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: =
flag: no ignore_afs</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: =
pam_krb5[5473]: flag: user_check</DIV><DIV>Oct 25 12:13:52 rfs2 =
sshd[5473]: pam_krb5[5473]: flag: krb4_convert</DIV><DIV>Oct 25 12:13:52 =
rfs2 sshd[5473]: pam_krb5[5473]: flag: warn</DIV><DIV>Oct 25 12:13:52 =
rfs2 sshd[5473]: pam_krb5[5473]: ticket lifetime: 36000</DIV><DIV>Oct 25 =
12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: renewable lifetime: =
36000</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: banner: =
Kerberos 5</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: =
ccache dir: /tmp</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: =
pam_krb5[5473]: keytab: /etc/krb5.keytab</DIV><DIV>Oct 25 12:13:52 rfs2 =
sshd[5473]: pam_krb5[5473]: no v5 creds for user 'seiffert', skipping =
session setup</DIV><DIV>Oct 25 12:13:52 rfs2 sshd[5473]: pam_krb5[5473]: =
pam_open_session returning 0 (Success)</DIV><DIV>Oct 25 12:13:52 rfs2 =
pam_loginuid[5473]: set_loginuid failed opening loginuid =
</DIV></BLOCKQUOTE><DIV><BR><DIV><DIV style=3D"margin-top: 0px; =
margin-right: 0px; margin-bottom: 0px; margin-left: 0px; font: normal =
normal normal 12px/normal Helvetica; min-height: 14px; "><BR></DIV><DIV =
style=3D"margin-top: 0px; margin-right: 0px; margin-bottom: 0px; =
margin-left: 0px; "><FONT face=3D"Helvetica" size=3D"3" style=3D"font: =
12.0px Helvetica">Kurt A. Seiffert<SPAN class=3D"Apple-converted-space">=A0=
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 </SPAN>| <A =
href=3D"mailto:seiffert@indiana.edu">seiffert@indiana.edu</A></FONT></DIV>=
<DIV style=3D"margin-top: 0px; margin-right: 0px; margin-bottom: 0px; =
margin-left: 0px; "><FONT face=3D"Helvetica" size=3D"3" style=3D"font: =
12.0px Helvetica">UITS Distributed Storage Services Group | C: =
812-345-1892</FONT></DIV><DIV style=3D"margin-top: 0px; margin-right: =
0px; margin-bottom: 0px; margin-left: 0px; "><FONT face=3D"Helvetica" =
size=3D"3" style=3D"font: 12.0px Helvetica">Indiana University, =
Bloomington <SPAN class=3D"Apple-converted-space">=A0 =A0 =A0 =A0 =
</SPAN>| W: 1 812-855-5089<SPAN class=3D"Apple-converted-space">=A0 =A0 =
=A0</SPAN></FONT></DIV> </DIV><BR></DIV></DIV></DIV></BODY></HTML>=
--Apple-Mail-27--7310083--