You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by "Griffith, Michael *" <Mi...@fda.hhs.gov> on 2009/02/27 19:00:29 UTC
[users@httpd] Authentication Stuck in a loop!
Hello Fellow List Readers ...
I'm not sure if this is an Apache problem or CAS problem, or possibly a
problem with my application Acegi configuration.
I'm hoping someone can give me a shove in the right direction.
We have a CAS server 3.3.1 running under Jboss 4.0.2. The CAS Server is
configured to use the SPNEGO Authentication Handler.
I have a custom Java application which is a client, running under Jboss
4.2.3, fronted by Apache 2.2. using mod_jk.
In my local environment, authentication works exactly right, however,
when I deploy the application on my test server it looks as if the
authentication fails at the application level, but the log file from the
CAS server doesn't seem to indicate it. Both localhost and test server
are configured exactly the same way, except I am logged into my
localhost and I am not on the Test Server.
Below is the access log files from Apache. You can see what is happening
with my test server is that it is going into an infinite loop, not being
able to log in.
Test Server Apache Access Log (Not working)
10.148.9.69 - - [26/Feb/2009:16:28:58 -0500] "GET
/Repository/component/list.action HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:16:28:59 -0500] "GET
/Repository/j_acegi_cas_security_check?ticket=ST-2172-FxfuJJVqXkwqflT5Ru
3d-cas HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:16:28:59 -0500] "GET
/Repository/public/login.action?login_error=1 HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:16:29:00 -0500] "GET
/Repository/j_acegi_cas_security_check?ticket=ST-2173-fj6p5HesGJygB5Kh6O
He-cas HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:16:29:00 -0500] "GET
/Repository/public/login.action?login_error=1 HTTP/1.1" 302 -
LocalHost Apache Access Log (Works fine)
10.148.9.69 - - [26/Feb/2009:14:14:08 -0600] "GET
/Repository/component/list.action HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:14:14:09 -0600] "GET
/Repository/j_acegi_cas_security_check;jsessionid=5EA5A6CA0FFF90402D9598
4401F4BA26?ticket=ST-1435-puHmdwa6WMzRsR5tq3K7-cas HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:14:14:09 -0600] "GET
/Repository/j_acegi_cas_security_check?ticket=ST-1435-puHmdwa6WMzRsR5tq3
K7-cas HTTP/1.1" 302 -
10.148.9.69 - - [26/Feb/2009:14:14:12 -0600] "GET
/Repository/component/list.action HTTP/1.1" 200 4080
My custom web app is using Acegi Security, configured to authenticate
using the CAS client.
You can see in the log file that the login appears to fail, and it goes
into an infinite loop. A response is never returned to the browser, and
the log file continues to grow with the same entries over and over.
Below is the log from the CAS Server, as far as I can tell, the CAS
server is not throwing any exceptions, or having trouble verifying the
user. From what I can tell, I think I have the debug info from one login
request below:
Any reply would be greatly appreciated!
++++
2009-02-26 21:45:29,107 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' completed execution; result is 'success'
2009-02-26 21:45:29,175 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' beginning execution
2009-02-26 21:45:29,177 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Authorization header not found. Sending WWW-Authenticate header
2009-02-26 21:45:29,178 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' completed execution; result is
'success'
2009-02-26 21:45:29,178 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' beginning execution
2009-02-26 21:45:29,179 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' completed execution; result is 'error'
2009-02-26 21:45:29,179 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' beginning execution
2009-02-26 21:45:29,189 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Executing setupForm
2009-02-26 21:45:29,191 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new form
object with name 'credentials'
2009-02-26 21:45:29,192 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new
instance of form object class [class
org.jasig.cas.authentication.principal.UsernamePasswordCredentials]
2009-02-26 21:45:29,193 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Putting form object
of type [class
org.jasig.cas.authentication.principal.UsernamePasswordCredentials] in
scope Flow with name 'credentials'
2009-02-26 21:45:29,194 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new form
errors for object with name 'credentials'
2009-02-26 21:45:29,221 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - No property editor
registrar set, no custom editors to register
2009-02-26 21:45:29,234 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Putting form errors
instance in scope Flash
2009-02-26 21:45:29,235 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' completed execution; result is 'success'
2009-02-26 21:45:29,235 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' beginning execution
2009-02-26 21:45:29,236 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' completed execution; result is 'success'
2009-02-26 21:45:34,587 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' beginning execution
2009-02-26 21:45:34,587 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.support.CasArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:45:34,588 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.support.SamlArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:45:34,588 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' completed execution; result is 'success'
2009-02-26 21:45:34,590 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' beginning execution
2009-02-26 21:45:34,591 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' completed execution; result is
'success'
2009-02-26 21:45:34,591 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' beginning execution
2009-02-26 21:45:34,592 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - SPNEGO
Authorization header found with 3796 bytes
2009-02-26 21:45:34,604 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Obtained
token!
2009-02-26 21:45:34,614 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.CentralAuthenticationServiceImpl - Attempting to create
TicketGrantingTicket for Principal is null Debug is true storeKey true
useTicketCache false useKeyTab true doNotPrompt false ticketCache is
null isInitiator true KeyTab is /opt/appian/FDSACASSPNacct.keytab
refreshKrb5Config is false principal is HTTP/fdssa144d.fda.gov@FDA.GOV
tryFirstPass is false useFirstPass is false storePass is false clearPass
is false
>>> KeyTabInputStream, readName(): FDA.GOV KeyTabInputStream,
>>> readName(): HTTP KeyTabInputStream, readName(): fdssa144d.fda.gov
>>> KeyTab: load() entry length: 57; type: 3
Added key: 3version: 6
Ordering keys wrt default_tkt_enctypes list Using builtin default etypes
for default_tkt_enctypes default etypes for default_tkt_enctypes: 3 1 23
16 17.
principal's key obtained from the keytab Acquire TGT using AS Exchange
Using builtin default etypes for default_tkt_enctypes default etypes for
default_tkt_enctypes: 3 1 23 16 17.
>>> KrbAsReq calling createMessage
>>> KrbAsReq in createMessage
>>> KrbKdcReq send: kdc=frs02.fda.gov UDP:88, timeout=30000, number of
retries =3, #bytes=145
>>> KDCCommunication: kdc=frs02.fda.gov UDP:88, timeout=30000,Attempt
=1, #bytes=145
>>> KrbKdcReq send: #bytes read=207
>>> KrbKdcReq send: #bytes read=207
>>> KDCRep: init() encoding tag is 126 req type is 11
>>>KRBError:
sTime is Thu Feb 26 21:45:34 GMT 2009 1235684734000
suSec is 189462
error code is 25
error Message is Additional pre-authentication required
realm is FDA.GOV
sname is krbtgt/FDA.GOV
eData provided.
msgType is 30
>>>Pre-Authentication Data:
PA-DATA type = 11
PA-ETYPE-INFO etype = 3
>>>Pre-Authentication Data:
PA-DATA type = 2
PA-ENC-TIMESTAMP
>>>Pre-Authentication Data:
PA-DATA type = 15
AcquireTGT: PREAUTH FAILED/REQUIRED, re-send AS-REQ Updated salt from
pre-auth = FDA.GOVHTTPfdssa144d.fda.gov
>>>KrbAsReq salt is FDA.GOVHTTPfdssa144d.fda.gov
Pre-Authenticaton: find key for etype = 3
AS-REQ: Add PA_ENC_TIMESTAMP now
>>> EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
>>> KrbAsReq calling createMessage
>>> KrbAsReq in createMessage
>>> KrbKdcReq send: kdc=frs02.fda.gov UDP:88, timeout=30000, number of
retries =3, #bytes=229
>>> KDCCommunication: kdc=frs02.fda.gov UDP:88, timeout=30000,Attempt
=1, #bytes=229
>>> KrbKdcReq send: #bytes read=1300
>>> KrbKdcReq send: #bytes read=1300
>>> EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
>>> KrbAsRep cons in KrbAsReq.getReply HTTP/fdssa144d.fda.gov
principal is HTTP/fdssa144d.fda.gov@FDA.GOV
EncryptionKey: keyType=3 keyBytes (hex dump)=0000: F7 C1 85 86 89 EF 04
25
Added server's keyKerberos Principal HTTP/fdssa144d.fda.gov@FDA.GOVKey
Version 6key EncryptionKey: keyType=3 keyBytes (hex dump)=
[Krb5LoginModule] added Krb5Principal HTTP/fdssa144d.fda.gov@FDA.GOV to
Subject Commit Succeeded Found key for HTTP/fdssa144d.fda.gov@FDA.GOV(3)
Entered Krb5Context.acceptSecContext with state=STATE_NEW
>>> EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
Using builtin default etypes for permitted_enctypes default etypes for
permitted_enctypes: 3 1 23 16 17.
>>> EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
>>> Config reset default kdc FDA.GOV
replay cache for Michael.Griffith@FDA.GOV is null.
object 0: 1235684735006/6622
object 0: 1235684735006/6622
>>> KrbApReq: authenticate succeed.
>>> EType: sun.security.krb5.internal.crypto.NullEType
>>>Delegated Creds have pname=Michael.Griffith@FDA.GOV
sname=krbtgt/FDA.GOV@FDA.GOV authtime=null starttime=20090226214531Z
endtime=20090227065112ZrenewTill=20090305205112Z
Krb5Context setting peerSeqNumber to: 145606174
>>> EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
Krb5Context setting mySeqNumber to: 255498812
2009-02-26 21:45:34,995 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.authentication.handler.support.JCIFSSpnegoA
uthenticationHandler - Setting nextToken in credentials
2009-02-26 21:45:34,996 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.authentication.handler.support.JCIFSSpnegoA
uthenticationHandler - Kerberos Credentials is valid for user
[Michael.Griffith@FDA.GOV]
2009-02-26 21:45:34,998 [http-0.0.0.0-8080-1] INFO
org.jasig.cas.authentication.AuthenticationManagerImpl -
AuthenticationHandler:
org.jasig.cas.support.spnego.authentication.handler.support.JCIFSSpnegoA
uthenticationHandler successfully authenticated the user which provided
the following credentials: Michael.Griffith
2009-02-26 21:45:34,998 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.authentication.principal.SpnegoCredentialsT
oPrincipalResolver - Attempting to resolve a principal...
2009-02-26 21:45:35,000 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.authentication.principal.SpnegoCredentialsT
oPrincipalResolver - Creating SimplePrincipal for [Michael.Griffith]
2009-02-26 21:45:35,032 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.ticket.registry.DefaultTicketRegistry - Added ticket
[TGT-1-Vivu9uKMdxEaJrtgcemPibBQT5PJbS9gOEICY6TP3Cezlu6FAy-cas] to
registry.
2009-02-26 21:45:35,033 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Obtained
output token!
2009-02-26 21:45:35,034 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' completed execution; result is 'success'
2009-02-26 21:45:35,035 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.flow.SendTicketGrantingTicketAction - Action
'SendTicketGrantingTicketAction' beginning execution
2009-02-26 21:45:35,036 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.support.CookieRetrievingCookieGenerator - Added cookie
with name [CASTGC] and value
[TGT-1-Vivu9uKMdxEaJrtgcemPibBQT5PJbS9gOEICY6TP3Cezlu6FAy-cas]
2009-02-26 21:45:35,037 [http-0.0.0.0-8080-1] DEBUG
org.jasig.cas.web.flow.SendTicketGrantingTicketAction - Action
'SendTicketGrantingTicketAction' completed execution; result is
'success'
2009-02-26 21:46:14,635 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' beginning execution
2009-02-26 21:46:14,636 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.support.CasArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:46:14,636 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.support.SamlArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:46:14,637 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' completed execution; result is 'success'
2009-02-26 21:46:14,638 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' beginning execution
2009-02-26 21:46:14,639 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Authorization header not found. Sending WWW-Authenticate header
2009-02-26 21:46:14,639 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' completed execution; result is
'success'
2009-02-26 21:46:14,640 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' beginning execution
2009-02-26 21:46:14,640 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' completed execution; result is 'error'
2009-02-26 21:46:14,641 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' beginning execution
2009-02-26 21:46:14,641 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Executing setupForm
2009-02-26 21:46:14,641 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new form
object with name 'credentials'
2009-02-26 21:46:14,642 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new
instance of form object class [class
org.jasig.cas.authentication.principal.UsernamePasswordCredentials]
2009-02-26 21:46:14,642 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Putting form object
of type [class
org.jasig.cas.authentication.principal.UsernamePasswordCredentials] in
scope Flow with name 'credentials'
2009-02-26 21:46:14,643 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Creating new form
errors for object with name 'credentials'
2009-02-26 21:46:14,643 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - No property editor
registrar set, no custom editors to register
2009-02-26 21:46:14,643 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Putting form errors
instance in scope Flash
2009-02-26 21:46:14,644 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' completed execution; result is 'success'
2009-02-26 21:46:14,644 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' beginning execution
2009-02-26 21:46:14,645 [http-0.0.0.0-8080-2] DEBUG
org.jasig.cas.web.flow.AuthenticationViaFormAction - Action
'AuthenticationViaFormAction' completed execution; result is 'success'
2009-02-26 21:46:57,568 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' beginning execution
2009-02-26 21:46:57,569 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.web.support.CasArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:46:57,569 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.web.support.SamlArgumentExtractor - Extractor did not
generate service.
2009-02-26 21:46:57,570 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.web.flow.InitialFlowSetupAction - Action
'InitialFlowSetupAction' completed execution; result is 'success'
2009-02-26 21:46:57,571 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' beginning execution
2009-02-26 21:46:57,571 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoNegociateCredentialsAction -
Action 'SpnegoNegociateCredentialsAction' completed execution; result is
'success'
2009-02-26 21:46:57,572 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Action
'SpnegoCredentialsAction' beginning execution
2009-02-26 21:46:57,572 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - SPNEGO
Authorization header found with 56 bytes
2009-02-26 21:46:57,573 [http-0.0.0.0-8080-3] DEBUG
org.jasig.cas.support.spnego.web.flow.SpnegoCredentialsAction - Obtained
token: NTLMSSP
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org