[Freeipa-users] sudden ipa errors.

Tue Sep 18 20:37:36 UTC 2012

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

IM going to respond inline to avoid confusion.

On 09/18/2012 03:22 PM, Rob Crittenden wrote:
> 
> I think we need to start with the basics, so here is a slew of 
> questions, things to try:
> 
> You said you enabled password auth? Did you do this by setting 
> KrbMethodK5Passwd to on?
> 

Yes, in /etc/conf.d/ipa.conf, I changed
KrbMethodK5Passwd from off to on, and reloaded httpd.

> You say that some commands work, which ones?
> 
There are very few that dont error out.  The ones i've come across are
things like, ipa-replica-manage, every ipa <command> command ive
attempted to run dies with:

[root at caroline0 PROD conf.d]# ipa user-show lagern
ipa: ERROR: cannot connect to
u'http://caroline0.lafayette.edu/ipa/xml': Internal Server Error

> It seems that kinit works? kinit admin
> 
kinit admin works, but admin's password is expired, so the session
never fully init's.  Before his password expired, i could kinit admin.
 I can still kinit as myself, which is an admin account.

> Can you set LogLevel debug in /etc/httpd/conf.d/nss.conf and
> restart the httpd service, then:
> 
> $ kdestroy $ kinit admin $ ipa user-show admin
> 
> Provide the logs covering the restart of Apache until the error
> from /var/log/httpd/error_log, /var/log/krb5kdc.log and 
> /var/log/dirsrv/slapd-YOURINSTANCE/access. This last log buffers
> for 30 seconds so it may be a while before it gets updated.
> 

loglevel is already debug due to my other testing.
I've restarted httpd anyway, in case you get any meaningful errors in
httpd's start procedure.

I then ran the commands you requested.  Here are the log outputs.

Im sorry that these are dumped in and hard to read..

/var/log/httpd/error_log:
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:45 2012] [error] Exception KeyError:
KeyError(140591752845280,) in <module 'threading' from
'/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Sep 18 16:26:46 2012] [notice] caught SIGTERM, shutting down
[Tue Sep 18 16:26:46 2012] [notice] SELinux policy enabled; httpd
running as context unconfined_u:system_r:httpd_t:s0
[Tue Sep 18 16:26:46 2012] [notice] suEXEC mechanism enabled (wrapper:
/usr/sbin/suexec)
[Tue Sep 18 16:26:47 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:47 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:47 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:47 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:47 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:47 2012] [notice] Digest: generating secret for
digest authentication ...
[Tue Sep 18 16:26:47 2012] [notice] Digest: done
[Tue Sep 18 16:26:47 2012] [warn] mod_wsgi: Compiled for Python/2.6.2.
[Tue Sep 18 16:26:47 2012] [warn] mod_wsgi: Runtime using Python/2.6.6.
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [notice] Apache/2.2.15 (Unix) DAV/2
mod_auth_kerb/5.4 mod_nss/2.2.15 NSS/3.13.1.0 Basic ECC mod_wsgi/3.2
Python/2.6.6 configured -- resuming normal operations
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [debug] proxy_util.c(1803): proxy: worker
ajp://localhost:9447/ already initialized
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [info] Configuring server for SSL protocol
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(655): Enabling SSL3
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(660): Enabling TLS
[Tue Sep 18 16:26:48 2012] [debug] nss_engine_init.c(831): Configuring
permitted SSL ciphers
[+rsa_rc4_128_md5,+rsa_rc4_128_sha,+rsa_3des_sha,-rsa_des_sha,-rsa_rc4_40_md5,-rsa_rc2_40_md5,-rsa_null_md5,-rsa_null_sha,+fips_3des_sha,-fips_des_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-rsa_des_56_sha,-rsa_rc4_56_sha,+rsa_aes_128_sha,+rsa_aes_256_sha]
[Tue Sep 18 16:26:48 2012] [info] Using nickname Server-Cert.
[Tue Sep 18 16:26:52 2012] [error] ipa: INFO: *** PROCESS START ***
[Tue Sep 18 16:26:52 2012] [error] ipa: INFO: *** PROCESS START ***
[Tue Sep 18 16:27:06 2012] [info] Connection to child 1 established
(server caroline0.lafayette.edu:443, client 139.147.7.204)
[Tue Sep 18 16:27:06 2012] [info] Initial (No.1) HTTPS request
received for child 1 (server caroline0.lafayette.edu:443)
[Tue Sep 18 16:27:06 2012] [debug] src/mod_auth_kerb.c(1939): [client
139.147.7.204] kerb_authenticate_user entered with user (NULL) and
auth_type Kerberos, referer: https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:06 2012] [debug] src/mod_auth_kerb.c(1278): [client
139.147.7.204] Acquiring creds for HTTP at caroline0.lafayette.edu,
referer: https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:06 2012] [debug] src/mod_auth_kerb.c(1372): [client
139.147.7.204] Using principal
HTTP/caroline0.lafayette.edu at SYSTEMS.LAFAYETTE.EDU for s4u2proxy,
referer: https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:06 2012] [debug] src/mod_auth_kerb.c(1414): [client
139.147.7.204] Credentials for
HTTP/caroline0.lafayette.edu at SYSTEMS.LAFAYETTE.EDU will expire at
1348001920, it is now 1348000026, referer:
https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:06 2012] [debug] src/mod_auth_kerb.c(1597): [client
139.147.7.204] Done obtaining credentials for s4u2proxy, referer:
https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:08 2012] [debug] src/mod_auth_kerb.c(1138): [client
139.147.7.204] GSS-API major_status:000d0000, minor_status:00000000,
referer: https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:08 2012] [error] [client 139.147.7.204]
gss_acquire_cred() failed: Unspecified GSS failure.  Minor code may
provide more information (, Unknown error), referer:
https://caroline0.lafayette.edu/ipa/xml
[Tue Sep 18 16:27:08 2012] [info] [client 139.147.7.204] (32)Broken
pipe: core_output_filter: writing data to the network
[Tue Sep 18 16:27:08 2012] [info] Connection to child 1 closed (server
caroline0.lafayette.edu:443, client 139.147.7.204)

/var/log/krb5kdc.log:
Sep 18 16:26:55 caroline0.lafayette.edu krb5kdc[20842](info): AS_REQ
(4 etypes {18 17 16 23}) 139.147.7.204: NEEDED_PREAUTH:
lagern at SYSTEMS.LAFAYETTE.EDU for
krbtgt/SYSTEMS.LAFAYETTE.EDU at SYSTEMS.LAFAYETTE.EDU, Additional
pre-authentication required
Sep 18 16:26:59 caroline0.lafayette.edu krb5kdc[20842](info): AS_REQ
(4 etypes {18 17 16 23}) 139.147.7.204: ISSUE: authtime 1348000019,
etypes {rep=18 tkt=18 ses=18}, lagern at SYSTEMS.LAFAYETTE.EDU for
krbtgt/SYSTEMS.LAFAYETTE.EDU at SYSTEMS.LAFAYETTE.EDU
Sep 18 16:27:06 caroline0.lafayette.edu krb5kdc[20842](info): TGS_REQ
(4 etypes {18 17 16 23}) 139.147.7.204: ISSUE: authtime 1348000019,
etypes {rep=18 tkt=18 ses=18}, lagern at SYSTEMS.LAFAYETTE.EDU for
HTTP/caroline0.lafayette.edu at SYSTEMS.LAFAYETTE.EDU

/var/log/dirsrv/slapd-SYSTEMS-LAFAYETTE-EDU/access
[18/Sep/2012:16:26:47 -0400] conn=44 op=11 SRCH
base="cn=accounts,dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(uid=apache)(objectClass=posixAccount))" attrs="objectClass
uid userPassword uidNumber gidNumber gecos homeDirectory loginShell
krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn
shadowLastChange shadowMin shadowMax shadowWarning shadowInactive
shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration
pwdattribute authorizedService accountexpires useraccountcontrol
nsAccountLock host logindisabled loginexpirationtime
loginallowedtimemap ipaSshPubKey"
[18/Sep/2012:16:26:47 -0400] conn=44 op=11 RESULT err=0 tag=101
nentries=0 etime=0
[18/Sep/2012:16:26:54 -0400] conn=4 op=97 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=lagern at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:26:54 -0400] conn=4 op=97 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:54 -0400] conn=4 op=98 SRCH
base="cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=krbticketpolicyaux)"
attrs="krbMaxTicketLife krbMaxRenewableAge krbTicketFlags"
[18/Sep/2012:16:26:54 -0400] conn=4 op=98 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:54 -0400] conn=4 op=99 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/SYSTEMS.LAFAYETTE.EDU at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:26:54 -0400] conn=4 op=99 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:54 -0400] conn=4 op=100 SRCH
base="cn=global_policy,cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=*)" attrs="krbMaxPwdLife krbMinPwdLife
krbPwdMinDiffChars krbPwdMinLength krbPwdHistoryLength
krbPwdMaxFailure krbPwdFailureCountInterval krbPwdLockoutDuration"
[18/Sep/2012:16:26:54 -0400] conn=4 op=100 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:58 -0400] conn=4 op=102 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=lagern at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:26:58 -0400] conn=4 op=102 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:58 -0400] conn=4 op=103 SRCH
base="cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=krbticketpolicyaux)"
attrs="krbMaxTicketLife krbMaxRenewableAge krbTicketFlags"
[18/Sep/2012:16:26:58 -0400] conn=4 op=103 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:58 -0400] conn=4 op=104 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/SYSTEMS.LAFAYETTE.EDU at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:26:58 -0400] conn=4 op=104 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:58 -0400] conn=4 op=105 SRCH
base="cn=global_policy,cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=*)" attrs="krbMaxPwdLife krbMinPwdLife
krbPwdMinDiffChars krbPwdMinLength krbPwdHistoryLength
krbPwdMaxFailure krbPwdFailureCountInterval krbPwdLockoutDuration"
[18/Sep/2012:16:26:58 -0400] conn=4 op=105 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:26:58 -0400] conn=4 op=106 MOD
dn="uid=lagern,cn=users,cn=accounts,dc=systems,dc=lafayette,dc=edu"
[18/Sep/2012:16:26:58 -0400] conn=4 op=106 RESULT err=0 tag=103
nentries=0 etime=0 csn=5058d913000000040000
[18/Sep/2012:16:27:05 -0400] conn=4 op=107 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/SYSTEMS.LAFAYETTE.EDU at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:27:05 -0400] conn=4 op=107 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:27:05 -0400] conn=4 op=108 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=HTTP/caroline0.lafayette.edu at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:27:05 -0400] conn=4 op=108 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:27:05 -0400] conn=4 op=109 SRCH
base="cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=krbticketpolicyaux)"
attrs="krbMaxTicketLife krbMaxRenewableAge krbTicketFlags"
[18/Sep/2012:16:27:05 -0400] conn=4 op=109 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:27:05 -0400] conn=4 op=110 SRCH
base="dc=systems,dc=lafayette,dc=edu" scope=2
filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=lagern at SYSTEMS.LAFAYETTE.EDU))"
attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey
krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration
krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange
krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth
krbLoginFailedCount krbExtraData krbLastAdminUnlock
krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge
nsAccountLock passwordHistory objectClass"
[18/Sep/2012:16:27:05 -0400] conn=4 op=110 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:27:05 -0400] conn=4 op=111 SRCH
base="cn=SYSTEMS.LAFAYETTE.EDU,cn=kerberos,dc=systems,dc=lafayette,dc=edu"
scope=0 filter="(objectClass=krbticketpolicyaux)"
attrs="krbMaxTicketLife krbMaxRenewableAge krbTicketFlags"
[18/Sep/2012:16:27:05 -0400] conn=4 op=111 RESULT err=0 tag=101
nentries=1 etime=0
[18/Sep/2012:16:27:22 -0400] conn=49 fd=67 slot=67 connection from
139.147.7.205 to 139.147.7.204
[18/Sep/2012:16:27:22 -0400] conn=49 op=0 UNBIND
[18/Sep/2012:16:27:22 -0400] conn=49 op=0 fd=67 closed - U1
[18/Sep/2012:16:29:27 -0400] conn=50 fd=67 slot=67 connection from
139.147.7.204 to 139.147.7.204
[18/Sep/2012:16:29:27 -0400] conn=50 op=0 UNBIND
[18/Sep/2012:16:29:27 -0400] conn=50 op=0 fd=67 closed - U1

> What are the versions of:
> 
> httpd
[root at caroline0 PROD ~]# rpm -qa | grep httpd
httpd-2.2.15-15.el6_2.1.x86_64

> mod_auth_kerb
[root at caroline0 PROD ~]# rpm -qa | grep mod_auth_kerb
mod_auth_kerb-5.4-9.el6.x86_64

> ipa-server
[root at caroline0 PROD ~]# rpm -qa | grep ipa-server
ipa-server-selinux-2.2.0-16.el6.x86_64
ipa-server-2.2.0-16.el6.x86_64

> krb5-server
[root at caroline0 PROD ~]# rpm -qa | grep krb5-server
krb5-server-1.9-33.el6_3.2.x86_64
krb5-server-ldap-1.9-33.el6_3.2.x86_64

> 
> This is RHEL 6.3?
Yes.
[root at caroline0 PROD ~]# cat /etc/issue
Red Hat Enterprise Linux Server release 6.3 (Santiago)
Kernel \r on an \m

> 
> The problem seems isolated to mod_auth_kerb and/or s4u2proxy since
> it works with password authentication in the UI.
> 
> rob

- -- 
- -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
Nathan Lager, RHCSA, RHCE (#110-011-426)
System Administrator
11 Pardee Hall
Lafayette College, Easton, PA 18042
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.12 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://www.enigmail.net/

iEYEARECAAYFAlBY248ACgkQsZqG4IN3sukPpwCeJv+P6C/5odcVlj+2lXjLaXHT
AaAAnj4hDetnFZXWFfBrGRrWKp8lwckB
=UpQU
-----END PGP SIGNATURE-----