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@xxxxxxx 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@xxxxxxx EncryptionKey: keyType=3 keyBytes (hex dump)=0000: F7 C1 85 86 89 EF 04 25 Added server's keyKerberos Principal HTTP/fdssa144d.fda.gov@xxxxxxxxxx Version 6key EncryptionKey: keyType=3 keyBytes (hex dump)= [Krb5LoginModule] added Krb5Principal HTTP/fdssa144d.fda.gov@xxxxxxx to Subject Commit Succeeded Found key for HTTP/fdssa144d.fda.gov@xxxxxxx(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@xxxxxxx 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@xxxxxxx sname=krbtgt/FDA.GOV@xxxxxxx 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@xxxxxxx] 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@xxxxxxxxxxxxxxxx " from the digest: users-digest-unsubscribe@xxxxxxxxxxxxxxxx For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx
|