Thanks for the reply Marv,
I am hoping to avoid downloading the inspektr source and stepping through all
the code. I pretty sure it is some minor config error but I am not sure where
to look. My ticketRegistry.xml is right off the wiki for using memcahed.
I have this setting in my log4j.xml file, but it doesn't seem add any further
data.
<logger name="com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager">
<level value="DEBUG" />
<appender-ref ref="cas" />
</logger>
When I login I see this:
#|2012-04-18T14:45:26.091-0600|INFO|glassfish3.0.1|javax.enterprise.system.std.com.sun.enterprise.v3.services.impl|_ThreadID=28;_ThreadName=Thread-1;|2012-04-18
14:45:26,091 INFO [org.jas
ig.cas.authentication.AuthenticationManagerImpl] - <Principal found: u0519980>
|#]
[#|2012-04-18T14:45:26.132-0600|INFO|glassfish3.0.1|javax.enterprise.system.std.com.sun.enterprise.v3.services.impl|_ThreadID=28;_ThreadName=Thread-1;|Audit
trail record BEGIN
=============================================================
WHO: [username: u0519980]
WHAT: supplied credentials: [username: u0519980]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Wed Apr 18 14:45:26 MDT 2012
CLIENT IP ADDRESS: 128.110.140.67
SERVER IP ADDRESS: 155.97.166.161
=============================================================
|#]
[#|2012-04-18T14:45:26.577-0600|INFO|glassfish3.0.1|javax.enterprise.system.std.com.sun.enterprise.v3.services.impl|_ThreadID=28;_ThreadName=Thread-1;|Audit
trail record BEGIN
=============================================================
WHO: [username: u0519980]
WHAT: TGT-1-tBUkUHk2fZ7iKde3NBnsh0BXQrh0jdfbkdk5QSycTTqqWcbBPS-testcas2
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Apr 18 14:45:26 MDT 2012
CLIENT IP ADDRESS: 128.110.140.67
SERVER IP ADDRESS: 155.97.166.161
=============================================================
Here is the full stack trace when I logout:
[#|2012-04-18T14:45:48.882-0600|INFO|glassfish3.0.1|javax.enterprise.system.std.com.sun.enterprise.v3.services.impl|_ThreadID=28;_ThreadName=Thread-1;|2012-04-18
14:45:48,882 INFO [org.spr
ingframework.web.servlet.handler.SimpleUrlHandlerMapping] - <Mapped URL path
[/authorizationFailure.html] onto handler 'passThroughController'>
|#]
[#|2012-04-18T14:45:48.904-0600|INFO|glassfish3.0.1|org.hibernate.validator.engine.resolver.DefaultTraversableResolver|_ThreadID=28;_ThreadName=Thread-1;|Instantiated
an instance of org.hi
bernate.validator.engine.resolver.JPATraversableResolver.|#]
[#|2012-04-18T14:45:48.908-0600|INFO|glassfish3.0.1|org.hibernate.validator.engine.resolver.DefaultTraversableResolver|_ThreadID=28;_ThreadName=Thread-1;|Instantiated
an instance of org.hi
bernate.validator.engine.resolver.JPATraversableResolver.|#]
[#|2012-04-18T14:45:48.920-0600|INFO|glassfish3.0.1|javax.enterprise.system.std.com.sun.enterprise.v3.services.impl|_ThreadID=28;_ThreadName=Thread-1;|2012-04-18
14:45:48,920 INFO [org.spr
ingframework.web.servlet.DispatcherServlet] - <FrameworkServlet 'cas':
initialization completed in 193 ms>
|#]
[#|2012-04-18T14:45:51.023-0600|WARNING|glassfish3.0.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=28;_ThreadName=http-thread-pool-9022-(2);|StandardWrapperValve
[cas]: PWC1406: Servlet.service() for servlet cas threw exception
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:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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
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:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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 $Proxy134.destroyTicketGrantingTicket(Unknown Source)
at
org.jasig.cas.web.LogoutController.handleRequestInternal(LogoutController.java:64)
at
org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
at
org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
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.doGet(FrameworkServlet.java:549)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
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.StandardWrapper.service(StandardWrapper.java:1523)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:343)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
at
com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
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:256)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:277)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:188)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:641)
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:97)
at
com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:85)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:185)
at
org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:325)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:226)
at
com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:165)
at
com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:791)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:693)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:954)
at
com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:170)
at
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:135)
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:102)
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:88)
at
com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:76)
at
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:53)
at
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:57)
at com.sun.grizzly.ContextTask.run(ContextTask.java:69)
at
com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:330)
at
com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:309)
at java.lang.Thread.run(Thread.java:662)
|#]
[#|2012-04-18T14:45:51.023-0600|WARNING|glassfish3.0.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=28;_ThreadName=Thread-1;|StandardWrapperValve[cas]:
PWC1406: S
ervlet.service() for servlet cas threw exception
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:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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
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:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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 $Proxy134.destroyTicketGrantingTicket(Unknown Source)
at
org.jasig.cas.web.LogoutController.handleRequestInternal(LogoutController.java:64)
at
org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
at
org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
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.doGet(FrameworkServlet.java:549)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
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.StandardWrapper.service(StandardWrapper.java:1523)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:343)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
at
com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
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:256)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:215)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:277)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:188)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:641)
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:97)
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:97)
at
com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:85)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:185)
at
org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:325)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:226)
at
com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:165)
at
com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:791)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:693)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:954)
at
com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:170)
at
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:135)
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:102)
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:88)
at
com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:76)
at
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:53)
at
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:57)
at com.sun.grizzly.ContextTask.run(ContextTask.java:69)
at
com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:330)
at
com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:309)
at java.lang.Thread.run(Thread.java:662)
|#]
-----Original Message-----
From: Marvin Addison [mailto:[email protected]]
Sent: Wednesday, April 18, 2012 2:23 PM
To: [email protected]
Subject: Re: [cas-user] Memcached Ticket Registry - Unresolved
> Any ideas why switching from JPA ticket registry to memcached ticket registry
> would affect auditing? I upped inspektr logging to debug but don't see any
> addition log information.
The exception you cited below offers only a hint, but it's better than nothing.
> [#|2012-04-17T13:15:41.901-0600|WARNING|glassfish3.0.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=30;_ThreadName=http-thread-pool-9022-(3);|StandardWrapperValve
> [cas]: PWC1406: Servlet.service() for servlet cas threw exception
> 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:39)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
This can happen if both the try and catch blocks in handleAuditTrail both throw
exceptions, in which case the finally block that logs the audit entry has a
null resolver [1].
While the Inspektr docs say the resolver is supposed to handle all exceptions
internally, I've seen this error occur when I've got try {...} catch (Exception
e){...} in my resolvers. I haven't spent the time to track down specific
causes because it rarely happens, but your case fits the general outline.
A quick review of source for Inspektr 1.0.5.GA, which is the version that ships
with 3.4.11, indicates this could be the problem since the NPE is thrown when
an attempt is made to iterate over a collection that would be null in the
scenario I described. (I'm matching up line numbers from your stack trace.)
Unfortunately the only way for you to get more information is to add more
logging to Inspektr and recompile. I really think Inspektr should either
provide more protection or information for cases like these. I opened an issue
[2] along those lines long ago but never followed through on it. Maybe it's
time to pursue?
M
[1]
https://github.com/dima767/inspektr/blob/c1677b560687ff1954fe106c7a664780d86513eb/inspektr-audit/src/main/java/com/github/inspektr/audit/AuditTrailManagementAspect.java
[2] https://github.com/dima767/inspektr/issues/10
--
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
