using CallLoggingInterceptor on existing web app

[mlybarger]

i have a simple web app with a servlet or two. i'd like to use the org.jboss.aspects.logging.CallLoggingInterceptor to log method invocation on my existing running app without touching the deployed .war. i want to use the supplied interceptors and such to be able to quickly demonstrate to some folks in our group the power of using aspects.

i've got a stock release of jboss-4.0.1sp1. i enabled the transformer in the deploy/jboss-aop.deployer/META-INF/jboss-service.xml. i tried adding a section to the deploy/jboss-aop.deployer/base-aop.xml to bind the interceptor to my servlet like such:

 <bind pointcut="execution(* org.test.*-&gt;*(..))">
 <interceptor class="org.jboss.aspects.logging.CallLoggingInterceptor"/>
 </bind>

i set the root logger to debug level in the log4j.xml. when calling my servlet i don't see any additional logging from the CallLoggingInterceptor. I'm certainly missing something here...?

[kabirkhan]

Download jboss aop 1.3 and install in your version of JBoss. I am not 100% sure if this will work, so if you can download the JBoss 4.0.3 release candidate.

Having done that refer to sections 10.3.2 and 10.3.3 depending on what JDK you are using for how to enable the class loading hooks.

Note that in the latest version of JBoss AOP the attribute on the AspectManager service has been changed to EnableLoadtimeWeaving.

[mlybarger]

thanks for the reply Khan. I've went through the document and am still having troubles. i noticed that originally i had forgot to specify the -javaagent:plugableinstrumentor.jar as part of the JAVA_OPTS variable. i've now put that jar into the jboss bin folder and added the parameter to the JAVA_OPTS variable. i also upgraded to the 1.3 jboss aop, and to the jboss 4.0.2.

i have an orgtest-aop.xml file in the server/default/deploy folder that looks like:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE aop PUBLIC
 "-//JBoss//DTD JBOSS AOP 1.0//EN"
 "http://www.jboss.org/aop/dtd/jboss-aop_1_0.dtd">
<aop>
 <bind pointcut="execution(* org.test.ProfileTest-&gt;*(..))">
 <interceptor class="org.jboss.aspects.logging.CallLoggingInterceptor"/>
 </bind>
</aop>

but still when running my web app, i have nothing being logged. still i must be missing someting. any help would be most appreciated, thanks!

[kabirkhan]

Did you set the EnableLoadtimeWeaving attribute of the AspectManagerService to true. Try the "injboss" tutorial example (docs/aspect-framework/examples/injboss), some extra info about getting it to work with the latest aop release here http://www.jboss.org/index.html?module=bb&op=viewtopic&t=65741

kabir

[mlybarger]

yes, i set the attribute you mentioned. i used the jboss-aop-jdk50.deployer from the 1.3 aop release. here's my jboss-service.xml.

<server>

 <mbean code="org.jboss.aop.deployment.AspectManagerService"
 name="jboss.aop:service=AspectManager">
 <attribute name="EnableLoadtimeWeaving">true</attribute>
 <!-- only relevant when EnableLoadtimeWeaving is true.
 When transformer is on, every loaded class gets
 transformed. If AOP can't find the class, then it
 throws an exception. Sometimes, classes may not have
 all the classes they reference. So, the Suppressing
 is needed. (i.e. Jboss cache in the default configuration -->
 <attribute name="SuppressTransformationErrors">true</attribute>
 <attribute name="Prune">true</attribute>
 <attribute name="Include">org.jboss.test</attribute>
 <attribute name="Exclude">org.jboss.</attribute>
 <attribute name="Optimized">true</attribute>
 <attribute name="Verbose">true</attribute>
 </mbean>

 <mbean code="org.jboss.aop.deployment.AspectDeployer"
 name="jboss.aop:service=AspectDeployer">
 </mbean>

</server>

in the post you linked to, you say to use the AspectManagerServiceJDK5. is this indeed needed? if so, i think the jboss-serivce.xml that is included in the jboss-aop-jdk50.deployer release should have this set as this service is specifically intended for jdk50 (uses -javaagent).

once again, thanks for your help with all this.

[mlybarger]

one more question. (there seems to be no editing of your posts in this forum as i'm use to in forums.gentoo.org).. do i need to set the include attribute to include a pattern for the classes i'm interested in testing? org.test.*?

thanks!

[kabirkhan]

1) Yes you need to use the AspectManagerServiceJDK5 service this is needed for the -javaagent to take effect- I have updated the documentation for the next release to make this cleare.

2) You only need to set the Include attribute if they would otherwise be picked up by the Exclude attribute.
In the snippet above everything under org.jboss gets excluded apart from org.jboss.test. So org.jboss.whatever.* would be excluded. org.acme.* would be included.
The reason for mentioning this was that the "injboss" example's classes are in org.jboss.injbossaop and would be excluded using the out of the box setup.

[mlybarger]

I'm now getting very close i think. after changing to use the AspectManagerServiceJDK5, i now get lots of aspect info in the logs. I see this when my class is loaded:

21:23:24,329 INFO [STDOUT] method matched binding execution(* org.test.*->*(..)) protected void org.test.ProfTest.doGet(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) throws javax.servlet.ServletException,java.io.IOException

but when this method is executed, i don't see anything being logged. here's the snipped from the base-aop.xml for what i'm binding.:

 <interceptor class="org.jboss.aspects.logging.CallLoggingInterceptor"/>
 <bind pointcut="execution(* org.test.*-&gt;*(..))">
 <interceptor-ref name="org.jboss.aspects.logging.CallLoggingInterceptor"/>
 </bind>

[kabirkhan]

Did the injboss example work for you? Get that working first, that should help get over any configuration issues.

CallLoggingInterceptor logs using DEBUG lever messages, have you got dEBUG logging turned on?

Maybe try with a real simple interceptor just to make sure you get it up and running.

[kabirkhan]

OK, so I can't type: I meant


CallLoggingInterceptor logs using DEBUG level messages, have you got DEBUG logging turned on?

[mlybarger]

i do have debug logging turned on, but i'll add some explicit log4j logging in my servlet to make sure in my example of using the CallLoggingInterceptor.

i was unsuccessfull with the injboss example. i gave the jboss.dir needed in the build.xml, then ran ant deploy-basic-lt-war. I point my browser to http://localhost:8080/aopexample and run the example. there's a lot of output on the first run when the classes are going through any transform. when running, i only see the output from the ExampleValue class and the BasicExampleServlet class. I see the same results in the console and the server/default/log/server.log file.

06:31:12,858 INFO [STDOUT] [trying to transform] org.apache.catalina.core.ApplicationDispatcher
06:31:12,859 INFO [STDOUT] [debug] There are no caller pointcuts!
06:31:12,932 INFO [STDOUT] [debug] was org.apache.catalina.core.ApplicationDispatcher converted: false
06:31:12,959 INFO [STDOUT] [trying to transform] org.apache.catalina.core.ApplicationHttpResponse
06:31:12,960 INFO [STDOUT] [debug] There are no caller pointcuts!
06:31:12,963 INFO [STDOUT] [debug] was org.apache.catalina.core.ApplicationHttpResponse converted: false
06:31:12,988 INFO [STDOUT] [trying to transform] org.apache.catalina.core.ApplicationResponse
06:31:12,989 INFO [STDOUT] [debug] There are no caller pointcuts!
06:31:12,991 INFO [STDOUT] [debug] was org.apache.catalina.core.ApplicationResponse converted: false
06:31:13,011 INFO [STDOUT] [trying to transform] org.apache.catalina.core.ApplicationHttpRequest
06:31:13,012 INFO [STDOUT] [debug] There are no caller pointcuts!
06:31:13,022 INFO [STDOUT] [debug] was org.apache.catalina.core.ApplicationHttpRequest converted: false
06:31:13,048 INFO [STDOUT] [trying to transform] org.apache.catalina.core.ApplicationRequest
06:31:13,050 INFO [STDOUT] [debug] There are no caller pointcuts!
06:31:13,052 INFO [STDOUT] [debug] was org.apache.catalina.core.ApplicationRequest converted: false
06:31:13,082 INFO [STDOUT] **** ExampleValue.getMessage()
06:31:38,315 INFO [STDOUT] **** BasicExampleServlet.service()
06:31:38,316 INFO [STDOUT] **** ExampleValue String Constructor
06:31:38,317 INFO [STDOUT] **** ExampleValue.getMessage()
06:31:52,624 INFO [STDOUT] **** BasicExampleServlet.service()
06:31:52,624 INFO [STDOUT] **** ExampleValue String Constructor
06:31:52,626 INFO [STDOUT] **** ExampleValue.getMessage()
06:32:31,721 INFO [STDOUT] **** BasicExampleServlet.service()
06:32:31,722 INFO [STDOUT] **** ExampleValue String Constructor
06:32:31,723 INFO [STDOUT] **** ExampleValue.getMessage()

i expected to see more output when running the servlet.

[mlybarger]

any ideas why the aopexample output shown above doesn't appear to have the interceptors being applied to the pointcuts? the SimpleInterceptor seems to be just using System.out.prinln to log that it's working, but i can't see that happening.

i'd really like to get to learn and use jboss aop in a dynamic web environment....

[kabirkhan]

Have you followed the steps outlined here?
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=65741

especially note that org.jboss.injbossaop must be added to the Include attribute of the aspect manager service. In 1.3.1 I have added this so it should work out of the box

[kabirkhan]

Actually, post your jboss-aop-jdk50.deployer/META-INF/jboss-service.xml

[mlybarger]

i think the include was what was tripping me up on the examples. i finally got it working!!

then i tried my servlet again to use the CallLoggingInterceptor. Still no luck. Then I added a SimpleInterceptor right into my war. Again, the war isn't aspectized, I'm using the load type weaving w/ jdk 1.5. i started to get logging exceptions that seemd to be recursive aop calls to botht eh CallLoggingInterceptor and the SimpleInterceptor. Then I completely shut off the CallLoggingInterceptor in the base-aop.xml. Finally, i've got a simple interceptor working with my war!

I'm still not sure why the CallLoggingInterceptor wasn't working. I have debug log4j logging in my servlet configured explicitly as:

 Logger LOG = Logger.getLogger( SnoopServlet.class );
 {
 BasicConfigurator.configure();
 LOG.setLevel( Level.DEBUG );
 }

i could see the debug logs from my servlet in the console, but nothing from the CallLoggingInterceptor.