Double-entry on pointcut?

[cuplan]

I hope this is the correct forum to be posting this to. FCCI's system architect has scrounged up a little work time for me to start our development of our AOP system monitoring ideas. I won't bore people with the details at this juncture, but suffice it to say that one of the pointcuts we need to have is across a common entry point for our Servlets. Now, I've been quite able to get interceptors to pointcut on a base class still under JBoss classloader control like javax.servlet.http.HttpServlet. What's interesting, though, is thatif we use a basic Interceptor like the TracingInterceptor from the AOP demos, the call to the service() method of HttpServlet shows two entrances to the method on the same thread. Curious about this, I dumped the stacktraces and got the following:

10:25:50,960 INFO [STDOUT] Entering method: service on thread PoolThread-4
10:25:50,960 INFO [STDOUT] Stacktrace:
10:25:50,960 ERROR [STDERR] java.lang.Exception: Stack trace
10:25:50,960 ERROR [STDERR] at java.lang.Thread.dumpStack(Thread.java:1071)
10:25:50,960 ERROR [STDERR] at TracingInterceptor.invoke(TracingInterceptor.java:51)
10:25:50,960 ERROR [STDERR] at org.jboss.aop.Invocation.invokeNext(Invocation.java:93)
10:25:50,960 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:411)
10:25:50,960 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:386)
10:25:50,960 ERROR [STDERR] at javax.servlet.http.HttpServlet._added_m$0(HttpServlet.java)
10:25:50,960 ERROR [STDERR] at javax.servlet.http.HttpServlet.service(HttpServlet.java)
10:25:50,970 ERROR [STDERR] at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:360)
10:25:50,970 ERROR [STDERR] at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:294)
10:25:50,970 ERROR [STDERR] at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:558)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpContext.handle(HttpContext.java:1714)
10:25:50,970 ERROR [STDERR] at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:507)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpContext.handle(HttpContext.java:1664)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpServer.service(HttpServer.java:861)
10:25:50,970 ERROR [STDERR] at org.jboss.jetty.Jetty.service(Jetty.java:497)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpConnection.service(HttpConnection.java:773)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:935)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.HttpConnection.handle(HttpConnection.java:790)
10:25:50,970 ERROR [STDERR] at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:201)
10:25:50,970 ERROR [STDERR] at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:289)
10:25:50,970 ERROR [STDERR] at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:454)
10:25:50,970 INFO [STDOUT] Entering method: service on thread PoolThread-4
10:25:50,970 INFO [STDOUT] Stacktrace:
10:25:50,970 ERROR [STDERR] java.lang.Exception: Stack trace
10:25:50,970 ERROR [STDERR] at java.lang.Thread.dumpStack(Thread.java:1071)
10:25:50,970 ERROR [STDERR] at TracingInterceptor.invoke(TracingInterceptor.java:51)
10:25:50,970 ERROR [STDERR] at org.jboss.aop.Invocation.invokeNext(Invocation.java:93)
10:25:50,970 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:411)
10:25:50,970 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:386)
10:25:50,970 ERROR [STDERR] at javax.servlet.http.HttpServlet._added_m$0(HttpServlet.java)
10:25:50,970 ERROR [STDERR] at javax.servlet.http.HttpServlet.service(HttpServlet.java)
10:25:50,970 ERROR [STDERR] at javax.servlet.http.HttpServlet.javax$servlet$http$HttpServlet$service$WithoutAdvisement(HttpServlet.java:853)
10:25:50,980 ERROR [STDERR] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
10:25:50,980 ERROR [STDERR] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
10:25:50,980 ERROR [STDERR] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
10:25:50,980 ERROR [STDERR] at java.lang.reflect.Method.invoke(Method.java:324)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeWithoutAdvisement(ClassAdvisor.java:349)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invoke(ClassAdvisor.java:563)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.Invocation.invokeNext(Invocation.java:93)
10:25:50,980 ERROR [STDERR] at TracingInterceptor.invoke(TracingInterceptor.java:52)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.Invocation.invokeNext(Invocation.java:93)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:411)
10:25:50,980 ERROR [STDERR] at org.jboss.aop.ClassAdvisor.invokeMethod(ClassAdvisor.java:386)
10:25:50,980 ERROR [STDERR] at javax.servlet.http.HttpServlet._added_m$0(HttpServlet.java)
10:25:50,980 ERROR [STDERR] at javax.servlet.http.HttpServlet.service(HttpServlet.java)
10:25:50,980 ERROR [STDERR] at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:360)
10:25:50,980 ERROR [STDERR] at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:294)
10:25:50,980 ERROR [STDERR] at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:558)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpContext.handle(HttpContext.java:1714)
10:25:50,980 ERROR [STDERR] at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:507)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpContext.handle(HttpContext.java:1664)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpServer.service(HttpServer.java:861)
10:25:50,980 ERROR [STDERR] at org.jboss.jetty.Jetty.service(Jetty.java:497)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpConnection.service(HttpConnection.java:773)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:935)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.HttpConnection.handle(HttpConnection.java:790)
10:25:50,980 ERROR [STDERR] at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:201)
10:25:50,980 ERROR [STDERR] at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:289)
10:25:50,980 ERROR [STDERR] at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:454)


As you can see, the two different entries into this method have some minor differences in their stacks. This is the only method that has a double entry on it...all the methods that appear to be "below" it on a normally expected thread of execution have one entry and one exit...nice and neat.

Any reason why this might be happening and how I can combat it? I'm sure it's just something I've overlooked on my side, but I'm a touch stumped.

[bill.burke]

Can you provide me with your pointcut definition? It may be a recursive call.

Bill

[cuplan]

Here is the pointcut def:

<interceptor-pointcut class="javax.servlet.http.HttpServlet">



</interceptor-pointcut>

The possiblity of a recursive call had not occurred to me; so thanks for the heads-up. It's quite obvious now that I've considered it.

Also, I will make sure I'm trying this with the most recent HEAD pull, thoush my source for JBoss should be recent.

[cuplan]

Oh, I just want to reiterate, too, that even thourgh the TracingInterceptor (which is only very slightly modified from the one in the ONJava examples) intercepts all method calls, it's only on the service() method call that I see this happening.

[bill.burke]

> Oh, I just want to reiterate, too, that even thourgh
> the TracingInterceptor (which is only very slightly
> modified from the one in the ONJava examples)
> intercepts all method calls, it's only on the
> service() method call that I see this happening.

DR2 has expanded pointcuts a lot. If the server call is recursive, then you might want to look into caller pointcuts