Unable to enable logging using CustomizableTraceInterceptor in Spring 3.0.6

[Daud Miyan]

I have a very simple setup

I have an applicationContext.xml file like this :

 <context:component-scan base-package="com.mkyong.common.controller" />

    <bean id="customizableTraceInterceptor"
        class="org.springframework.aop.interceptor.CustomizableTraceInterceptor">
        <property name="enterMessage" value="Entering $[methodName]($[arguments])" />
        <property name="exitMessage" value="Leaving $[methodName](): $[returnValue]" />
    </bean>
    <bean
        class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
        <property name="beanNames">
            <list>
                <value>*Service</value>
            </list>
        </property>
        <!-- <property name="proxyTargetClass" value="true" /> -->
        <property name="interceptorNames">
            <list>
                <value>customizableTraceInterceptor</value>
            </list>
        </property>
    </bean>
    <mvc:annotation-driven />

    <bean id="wowService" class="org.daud.WowService" scope="prototype" />
</beans>

The controller class is also very simple :

@Controller
@RequestMapping("/welcome")
public class HelloController {

    @Autowired
    private WowService wowService;

    @RequestMapping(method = RequestMethod.GET)
    public String printWelcome(ModelMap model) {

        getWowService().printIt();
        model.addAttribute("message", "Spring 3 MVC Hello World");
        return "hello";

    }

    public WowService getWowService() {
        return wowService;
    }

    public void setWowService(WowService wowService) {
        this.wowService = wowService;
    }

}

My web.xml is :

<?xml version="1.0" encoding="UTF-8"?> <web-app xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd" version="3.0" metadata-complete="true"> <display-name>simple-form</display-name> <listener> <listener-class> org.springframework.web.context.ContextLoaderListener </listener-class> </listener> <context-param> <param-name>contextConfigLocation</param-name> <param-value> /WEB-INF/applicationContext.xml </param-value> </context-param> <servlet> <servlet-name>simple-form</servlet-name> <servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class> <init-param> <param-name>contextConfigLocation</param-name> <param-value></param-value> </init-param> </servlet> <servlet-mapping> <servlet-name>simple-form</servlet-name> <url-pattern>/*</url-pattern> </servlet-mapping> <welcome-file-list> <welcome-file>index.jsp</welcome-file> </welcome-file-list> </web-app>

WowService is also very simple

public class WowService {

    public String printIt() {
        return "daud";

    }
}

I have the spring jars of version 3.0.6, aopalliance-1.0.jar, asm-3.1, cglib -2.2 and commons-logging-1.1.1.jar in my lib folder and nothing else. But there is no trace being recorded.. i.e there is no logging being done when we enter the method of WowService, or when we leave it. I can't figure out why.

[Mark Spritzler]

Two things.

In your web.xml you have the context-param for the ContextLoaderListener which is pointing to the /WEB-INF/applicationContext.xml file, which is the default location and name, which means you can remove the context-param entry and it works identical.

Also in your DispatcherServlet for the config file location you have it blank. Which I am guessing is because you put both your middle tier and web tier beans in the applicationContext.xml so in just one ApplicationContext, with two concerns mixed. While it works, it isn't a best practice.

Also for the logging, wouldnt you need a config/properties file for the configuration of logging? Meaning the interceptor could still be logging but the logging configuration isn't set up to put it anywhere you are looking? Not sure, just a guess here.

Mark

[Daud Miyan]

Thanks for that.. but I do have a logging.properties file in the classes folder, which is working fine, with the following content :

org.apache.catalina.core.ContainerBase.[Catalina].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].handlers = java.util.logging.ConsoleHandler

Its logging a lot of userful information, but not the one which the CustomizableTraceInterceptor is supposed to log. Sorry for not mentioning this earlier.

[Mark Spritzler]

Have you tried using

<aop:config>
  <aop:advisor advice-ref="customizableTraceInterceptor"
    pointcut="execution(public * org.springframework.data.jpa.repository.JpaRepository+.*(..))"/>
</aop:config>

to set it up where your pointcut would be for your service class, not what I just posted as an example that I copied and pasted from docs.

Instead of org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator bean you have.

Mark

[Daud Miyan]

Thanks. I tried that, and added the following :

<aop:config>  
      <aop:advisor advice-ref="customizableTraceInterceptor"  
        pointcut="execution(public * org.daud..*.*(..))"/>
</aop:config>

WowService is in the package org.daud. Unfortunately, it still doesn't work. I had to add the aspectJWeaver jar. Finally, I have the following jars in my lob folder :

aopalliance-1.0.jar
asm-3.1.jar
aspectjweaver-1.6.8.jar
cglib-2.2.jar
commons-logging-1.1.1.jar
org.springframework.aop-3.0.6.RELEASE.jar
org.springframework.asm-3.0.6.RELEASE.jar
org.springframework.aspects-3.0.6.RELEASE.jar
org.springframework.beans-3.0.6.RELEASE.jar
org.springframework.context.support-3.0.6.RELEASE.jar
org.springframework.context-3.0.6.RELEASE.jar
org.springframework.core-3.0.6.RELEASE.jar
org.springframework.expression-3.0.6.RELEASE.jar
org.springframework.instrument.tomcat-3.0.6.RELEASE.jar
org.springframework.instrument-3.0.6.RELEASE.jar
org.springframework.jdbc-3.0.6.RELEASE.jar
org.springframework.jms-3.0.6.RELEASE.jar
org.springframework.orm-3.0.6.RELEASE.jar
org.springframework.oxm-3.0.6.RELEASE.jar
org.springframework.test-3.0.6.RELEASE.jar
org.springframework.transaction-3.0.6.RELEASE.jar
org.springframework.web.portlet-3.0.6.RELEASE.jar
org.springframework.web.servlet-3.0.6.RELEASE.jar
org.springframework.web.struts-3.0.6.RELEASE.jar
org.springframework.web-3.0.6.RELEASE.jar

[Daud Miyan]

Kindly review my logger settings. I am not logging any trace information (simply because Commons Logging doesn't have TRACE level). Should I create log4j.properties also ?

[Mark Spritzler]

Not quite sure. But if you run your code through the debugger and set a break point before you call the service, you can check the variables pane to see if you have a reference to the real object or a proxy. Just to make sure you are getting proxied. Let us know.

Mark

[Daud Miyan]

Yes.... the wowService variable is getting proxied (CGLIB Bound = true)

[Mark Spritzler]

Daud Miyan wrote:Yes.... the wowService variable is getting proxied (CGLIB Bound = true)

Ok, now the next step. Step through the call to the service. If you can, can you download the SpringFramework sources. Then you can go into the CustomizableTraceInterceptor and put a break point in there to see if it is getting called. If you are using IntelliJ IDEA, it is really really easy. Just hit CTRL-N or Command-N on Mac, type in the class name Custom…. hit enter. Then at the top of the class file it will have a link to download the sources.

I don't know how to do it in Eclipse, if they even have such a feature. But you can download the source from www.github.com/springsource

Interesting that it uses CGLib to create a proxy, rather than the normal DynamicProxy class. Unless of course, your Service class is not implementing and interface and you aren't coding to interfaces which is a really really best practice for Java development.

Mark

[Daud Miyan]

Step through the call to the service. If you can, can you download the SpringFramework sources. Then you can go into the CustomizableTraceInterceptor and put a break point in there to see if it is getting called.

Did that, and saw that control was not coming inside the invokeUnderTrace() method. I checked the superclass, and found that in the invoke() method, the isInterceptorEnabled() was returning false. This method was checking whether the trace is enabled in the debugger.

I then figured that in logging.properties, I had configured only the apache packages to the the FINEST debug level (as posted above), and it wasn't considering spring classes for logging at that level. Therefore, I added the following at the end of logging.properties :

org.springframework.aop.interceptor.level = ALL
.handlers=java.util.logging.ConsoleHandler

After that, control began to enter in the invokeUnderTrace() method, and the logging statements got executed without a problem, but unfortunately, there was still no logging to be seen.

I am seeing the log of catalina.out. Since Spring uses Commons Logging, and i haven't configured Log4J or any other external logging framework, it uses java.util.Logging (the jdk14logger is the type of instances of the logger objects that are being formed, as show in the debugger), and as such logging.properties is being used. Should I look somewhere other than catalina.out ?

[Mark Spritzler]

Wouldn't your log file be something like

localhost.2012-02-08.log and not calalina.out. That is usually where I look.

Mark

[Daud Miyan]

localhost.2012-02-08.log - files like these get created when I stop my tomcat instance... whereas catalina.out is updated on the fly... Also, catalina.out has much more information than these files..

If don't know if its appropriate, but I can upload the war file somewhere and post a link to it here, because war files can't be uploaded here

[Mark Spritzler]

Daud Miyan wrote:localhost.2012-02-08.log - files like these get created when I stop my tomcat instance... whereas catalina.out is updated on the fly... Also, catalina.out has much more information than these files..

If don't know if its appropriate, but I can upload the war file somewhere and post a link to it here, because war files can't be uploaded here

But different log information goes into different log files. I never found any of my logging in catalina.out, I always had to go into localhost-.log file to see anything. They aren't the same log files.

Mark

[Daud Miyan]

According to this question, catalina.out is the file where stdout and stderr goes. Catalina.sh mentions this explicitly. Running this script also points to catalina.out

for PID in $(pgrep java);do sudo ls -l /proc/$PID/fd|grep ' ? -> ';done

as stated here. I am using Ubuntu 11.04 and am running tomcat 7.0.14 after extracting it from the tar file (i.e. not as a service)

[Daud Miyan]

I changed the logging.properties file in CATALINA_HOME/conf and replaced java.util.logging.ConsoleHandler.level = FINE with java.util.logging.ConsoleHandler.level = FINEST and now the trace started happening. But that, I suppose, is not the way to do things. When I placed the above line in my application's logging.properties (and reverted changes in tomcat's logging.properties), then no logs were printed for the trace. I can't figure out why

[Mark Spritzler]

"catalina.out is the file where stdout and stderr goes. "

Yeah, but that is not Commons Logging or Log4J. They strictly go to the file listed in their config file. Nothing to do with Tomcat/Catalina.

That is why it would show up in the localhost log file and never ever in catalina.out. stdout is System.out.println()

I suggest reading the commons logging documentation or even log4j documentation to understand what goes into log4j.properties or logging.properties.

Good Luck

Mark