Thanks Kevin, I've just seen this error in catalina.out:
2012-06-25 16:54:30,487 INFO
[org.jasig.cas.authentication.AuthenticationManagerImpl] -
<AuthenticationHandler: org.XXX.cas.XXXAuthHandler successfully authenticated
the user which provided the following credentials: [username: [email protected]]>
2012-06-25 16:54:30,487 DEBUG
[org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver]
- <Attempting to resolve a principal...>
2012-06-25 16:54:30,488 DEBUG
[org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver]
- <Creating SimplePrincipal for [[email protected]]>
2012-06-25 16:54:30,492 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit
trail record BEGIN
=============================================================
WHO: [username: [email protected]]
WHAT: java.lang.NullPointerException
ACTION: TICKET_GRANTING_TICKET_NOT_CREATED
APPLICATION: CAS
WHEN: Mon Jun 25 16:54:30 BST 2012
CLIENT IP ADDRESS: XX.XX.XX.XX
SERVER IP ADDRESS: XX.XX.XX.XX
=============================================================
>
2012-06-25 16:54:30,493 DEBUG
[org.springframework.jdbc.datasource.DataSourceUtils] - <Returning JDBC
Connection to DataSource>
2012-06-25 16:54:30,493 DEBUG
[org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction
rollback>
2012-06-25 16:54:30,493 DEBUG
[org.springframework.orm.jpa.JpaTransactionManager] - <Rolling back JPA
transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@62363bce]>
2012-06-25 16:54:30,494 DEBUG
[org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA
EntityManager [org.hibernate.ejb.EntityManagerImpl@62363bce] after transaction>
2012-06-25 16:54:30,494 DEBUG
[org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA
EntityManager>
2012-06-25 16:54:30,496 DEBUG
[org.springframework.webflow.execution.AnnotatedAction] - <Clearing action
execution attributes map[[empty]]>
2012-06-25 16:54:30,496 DEBUG
[org.springframework.webflow.engine.impl.FlowExecutionImpl] - <Attempting to
handle [org.springframework.webflow.execution.ActionExecutionException:
Exception thrown executing [AnnotatedAction@7f116790 targetAction =
[EvaluateAction@335e3974 expression =
authenticationViaFormAction.submit(flowRequestContext, flowScope.credentials,
messageContext), resultExpression = [null]], attributes = map[[empty]]] in
state 'realSubmit' of flow 'login' -- action execution attributes were
'map[[empty]]'] with root cause [java.lang.NullPointerException]>
2012-06-25 16:54:30,497 DEBUG
[org.springframework.webflow.engine.impl.FlowExecutionImpl] - <Rethrowing
unhandled flow execution exception>
2012-06-25 16:54:30,497 DEBUG
[org.springframework.webflow.conversation.impl.SessionBindingConversationManager]
- <Unlocking conversation 2>
2012-06-25 16:54:30,498 DEBUG
[org.springframework.web.servlet.DispatcherServlet] - <Could not complete
request>
org.springframework.webflow.execution.ActionExecutionException: Exception
thrown executing [AnnotatedAction@7f116790 targetAction =
[EvaluateAction@335e3974 expression =
authenticationViaFormAction.submit(flowRequestContext, flowScope.credentials,
messageContext), resultExpression = [null]], attributes = map[[empty]]] in
state 'realSubmit' of flow 'login' -- action execution attributes were
'map[[empty]]'
at
org.springframework.webflow.execution.ActionExecutor.execute(ActionExecutor.java:60)
at
org.springframework.webflow.engine.ActionState.doEnter(ActionState.java:101)
at org.springframework.webflow.engine.State.enter(State.java:194)
at
org.springframework.webflow.engine.Transition.execute(Transition.java:227)
at
org.springframework.webflow.engine.impl.FlowExecutionImpl.execute(FlowExecutionImpl.java:391)
at
org.springframework.webflow.engine.impl.RequestControlContextImpl.execute(RequestControlContextImpl.java:214)
at
org.springframework.webflow.engine.TransitionableState.handleEvent(TransitionableState.java:119)
at org.springframework.webflow.engine.Flow.handleEvent(Flow.java:555)
at
org.springframework.webflow.engine.impl.FlowExecutionImpl.handleEvent(FlowExecutionImpl.java:386)
at
org.springframework.webflow.engine.impl.RequestControlContextImpl.handleEvent(RequestControlContextImpl.java:210)
at
org.springframework.webflow.engine.ViewState.handleEvent(ViewState.java:254)
at
org.springframework.webflow.engine.ViewState.resume(ViewState.java:218)
at org.springframework.webflow.engine.Flow.resume(Flow.java:545)
at
org.springframework.webflow.engine.impl.FlowExecutionImpl.resume(FlowExecutionImpl.java:259)
at
org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:169)
at
org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:183)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:790)
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:644)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:560)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
at
org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody2(SafeDispatcherServlet.java:115)
at
org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody3$advice(SafeDispatcherServlet.java:44)
at
org.jasig.cas.web.init.SafeDispatcherServlet.service(SafeDispatcherServlet.java:1)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at
com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
at
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
at
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:987)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:539)
at
org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:1773)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by: org.springframework.binding.expression.EvaluationException: An
OgnlException occurred getting the value for expression
'authenticationViaFormAction.submit(flowRequestContext, flowScope.credentials,
messageContext)' on context [class
org.springframework.webflow.engine.impl.RequestControlContextImpl]
at
org.springframework.binding.expression.ognl.OgnlExpression.getValue(OgnlExpression.java:92)
at
org.springframework.webflow.action.EvaluateAction.doExecute(EvaluateAction.java:75)
at
org.springframework.webflow.action.AbstractAction.execute(AbstractAction.java:188)
at
org.springframework.webflow.execution.AnnotatedAction.execute(AnnotatedAction.java:145)
at
org.springframework.webflow.execution.ActionExecutor.execute(ActionExecutor.java:51)
... 49 more
Caused by: ognl.MethodFailedException: Method "submit" failed for object
org.jasig.cas.web.flow.AuthenticationViaFormAction@733e4c83
[java.lang.NullPointerException]
at ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1265)
at ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:68)
at ognl.OgnlRuntime.callMethod(OgnlRuntime.java:1329)
at ognl.ASTMethod.getValueBody(ASTMethod.java:90)
at ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)
at ognl.SimpleNode.getValue(SimpleNode.java:258)
at ognl.ASTChain.getValueBody(ASTChain.java:141)
at ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)
at ognl.SimpleNode.getValue(SimpleNode.java:258)
at ognl.Ognl.getValue(Ognl.java:494)
at
org.springframework.binding.expression.ognl.OgnlExpression.getValue(OgnlExpression.java:85)
... 53 more
Caused by: java.lang.NullPointerException
at
com.github.inspektr.audit.AuditTrailManagementAspect.executeAuditCode(AuditTrailManagementAspect.java:147)
at
com.github.inspektr.audit.AuditTrailManagementAspect.handleAuditTrail(AuditTrailManagementAspect.java:139)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy50.authenticate(Unknown Source)
at
org.jasig.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket_aroundBody10(CentralAuthenticationServiceImpl.java:413)
at
org.jasig.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket_aroundBody11$advice(CentralAuthenticationServiceImpl.java:44)
at
org.jasig.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(CentralAuthenticationServiceImpl.java:1)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at
org.perf4j.aop.AbstractTimingAspect$1.proceed(AbstractTimingAspect.java:47)
at
org.perf4j.aop.AgnosticTimingAspect.runProfiledMethod(AgnosticTimingAspect.java:53)
at
org.perf4j.aop.AbstractTimingAspect.doPerfLogging(AbstractTimingAspect.java:45)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at
org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at
com.github.inspektr.audit.AuditTrailManagementAspect.handleAuditTrail(AuditTrailManagementAspect.java:126)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy51.createTicketGrantingTicket(Unknown Source)
at
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit_aroundBody2(AuthenticationViaFormAction.java:95)
at
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit_aroundBody3$advice(AuthenticationViaFormAction.java:44)
at
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit(AuthenticationViaFormAction.java:1)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at ognl.OgnlRuntime.invokeMethod(OgnlRuntime.java:830)
at ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1253)
... 63 more
This looks like the culprit...
Cheers,
Nathan
On 25 Jun 2012, at 16:46, Kevin P. Foote wrote:
>
> I've set pretty much everything in stock log4j.xml to DEBUG and added
> some of my own explicit defs there as well..
>
> I'm currently getting what I think I should and usually see the base
> cause of a thread dump.
>
> To clarify your not getting anything that would trace back to the
> underlying cause.. in cas.log or catalina.out?
>
>
> ------
> thanks
> kevin.foote
>
> On Mon, 25 Jun 2012, Nathan Ducey wrote:
>
> -> Thanks for the suggestion Kevin, I've set them to DEBUG and now the user
> is still authenticated correctly (valid user), but there are now no further
> details of the error. Do you know if there's another way to see the errors
> please?
> ->
> -> Thanks,
> -> Nathan
> ->
> -> On 25 Jun 2012, at 16:20, Kevin P. Foote wrote:
> ->
> -> >
> -> > Do you have the org.springframework and org.springframework.webflow set
> to DEBUG?
> -> >
> -> > ------
> -> > thanks
> -> > kevin.foote
> -> >
> -> > On Mon, 25 Jun 2012, Nathan Ducey wrote:
> -> >
> -> > -> Hi,
> -> > ->
> -> > -> CAS is correctly authenticating a user and is currently displaying a
> "CAS is unavailable" error message when it tries to create the Principal.
> However I can't get any error messages about what is failing or why. I've
> changed the log type to DEBUG, but I still only see these errors in the
> cas.log file.
> -> > ->
> -> > -> 2012-06-25 16:11:30,520 INFO
> [org.jasig.cas.authentication.AuthenticationManagerImpl] -
> AuthenticationHandler:
> org.jasig.cas.adaptors.jdbc.SearchModeSearchDatabaseAuthenticationHandler
> successfully authenticated the user which provided the following credentials:
> [username: [email protected]]
> -> > -> 2012-06-25 16:11:30,521 DEBUG
> [org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver]
> - Attempting to resolve a principal...
> -> > -> 2012-06-25 16:11:30,521 DEBUG
> [org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver]
> - Creating SimplePrincipal for [[email protected]]
> -> > -> 2012-06-25 16:11:30,525 INFO
> [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit
> trail record BEGIN
> -> > -> =============================================================
> -> > -> WHO: [username: [email protected]]
> -> > -> WHAT: java.lang.NullPointerException
> -> > -> ACTION: TICKET_GRANTING_TICKET_NOT_CREATED
> -> > -> APPLICATION: CAS
> -> > -> WHEN: Mon Jun 25 16:11:30 BST 2012
> -> > -> CLIENT IP ADDRESS: 192.168.1.8
> -> > -> SERVER IP ADDRESS: 192.168.1.27
> -> > -> =============================================================
> -> > ->
> -> > -> Is there a way to see what is causing the NullPointerException which
> the Audit trail is referencing please?
> -> > ->
> -> > -> Thanks,
> -> > -> Nathan
> -> > -> --
> -> > -> You are currently subscribed to [email protected] as:
> [email protected]
> -> > -> To unsubscribe, change settings or access archives, see
> http://www.ja-sig.org/wiki/display/JSG/cas-user
> -> > ->
> -> > ->
> -> >
> -> > --
> -> > You are currently subscribed to [email protected] as:
> [email protected]
> -> > To unsubscribe, change settings or access archives, see
> http://www.ja-sig.org/wiki/display/JSG/cas-user
> ->
> ->
> -> --
> -> You are currently subscribed to [email protected] as:
> [email protected]
> -> To unsubscribe, change settings or access archives, see
> http://www.ja-sig.org/wiki/display/JSG/cas-user
> ->
> ->
>
> --
> You are currently subscribed to [email protected] as:
> [email protected]
> To unsubscribe, change settings or access archives, see
> http://www.ja-sig.org/wiki/display/JSG/cas-user
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
