Published on Oct 12 2012 in Java Tomcat

Increasing logging verbosity of a Java application can be helpful in quick problem identification and resolution as error messages with default Tomcat logging settings can be quite vague.

Default logger in Tomcat 6 and 7 is java.util.logging logger. Previously Log4J was used. See an example how increased logging verbosity helps solving an issue. When deploying fresh Grails application all error messages we initially got were:

INFO: Deploying web application archive /home/grailswebapp/appservers/apache-tomcat-7.0.30/webapps/grailswebapp.war
Configuring Spring Security Core ...
... finished configuring Spring Security Core
Oct 12, 2012 4:00:37 PM org.apache.catalina.core.StandardContext startInternal
SEVERE: Error listenerStart
Oct 12, 2012 4:00:37 PM org.apache.catalina.core.StandardContext startInternal
SEVERE: Context [/tixomatic] startup failed due to previous errors

Quite unclear information, not leading straight to a reason and solution. Let's now stop the Tomcat and put logging.properties file into application's WEB-INF/classes with the following content:

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

Clear catalina.out and start Tomcat. Now we get (scroll right to see Access denied for user message):


INFO: Deploying web application archive /home/grailswebapp/appservers/apache-tomcat-7.0.30/webapps/grailswebapp.war
Oct 12, 2012 4:13:37 PM org.apache.catalina.core.ApplicationContext log
INFO: No Spring WebApplicationInitializer types detected on classpath
Oct 12, 2012 4:13:38 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
Configuring Spring Security Core ...
... finished configuring Spring Security Core
Oct 12, 2012 4:13:42 PM org.apache.catalina.core.StandardContext listenerStart
SEVERE: Exception sending context initialized event to listener instance of class org.codehaus.groovy.grails.web.context.GrailsContextLoaderListener
    org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'transactionManagerPostProcessor': Initialization of bean failed; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'transactionManager': Cannot resolve reference to bean 'sessionFactory' while setting bean property 'sessionFactory'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sessionFactory': Cannot resolve reference to bean 'hibernateProperties' while setting bean property 'hibernateProperties'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'hibernateProperties': Cannot resolve reference to bean 'dialectDetector' while setting bean property 'properties' with key [hibernate.dialect]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dialectDetector': Invocation of init method failed; nested exception is org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData; nested exception is org.apache.commons.dbcp.SQLNestedException: Cannot create PoolableConnectionFactory (Access denied for user 'grailswebapp_dbuser1'@'server.company.net' (using password: YES))
     at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:527)
     at org.codehaus.groovy.grails.commons.spring.ReloadAwareAutowireCapableBeanFactory.doCreateBean(ReloadAwareAutowireCapableBeanFactory.java:126)
     at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
     at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
     at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
     at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
     at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
     at org.springframework.context.support.AbstractApplicationContext.registerBeanPostProcessors(AbstractApplicationContext.java:707)
     at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:449)
     at org.codehaus.groovy.grails.commons.spring.DefaultRuntimeSpringConfiguration.getApplicationContext(DefaultRuntimeSpringConfiguration.java:153)
     at org.codehaus.groovy.grails.commons.spring.GrailsRuntimeConfigurator.configure(GrailsRuntimeConfigurator.java:170)
     at org.codehaus.groovy.grails.commons.spring.GrailsRuntimeConfigurator.configure(GrailsRuntimeConfigurator.java:127)
     at org.codehaus.groovy.grails.web.context.GrailsConfigUtils.configureWebApplicationContext(GrailsConfigUtils.java:121)
     at org.codehaus.groovy.grails.web.context.GrailsContextLoader.initWebApplicationContext(GrailsContextLoader.java:104)
     at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:111)
     at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4791)
     at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5285)
     at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
     at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
     at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
     at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:618)
     at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:963)
     at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1600)
     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
     at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
     at java.util.concurrent.FutureTask.run(FutureTask.java:138)
     at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
     at java.lang.Thread.run(Thread.java:662)

and a few more related exceptions ending with

Oct 12, 2012 4:13:42 PM org.apache.catalina.core.StandardContext startInternal
SEVERE: Error listenerStart
Oct 12, 2012 4:13:42 PM org.apache.catalina.core.StandardContext startInternal
SEVERE: Context [/tixomatic] startup failed due to previous errors

It means somewhere in the code the database host was referenced with a host name different from localhost while only localhost access is granted or database credentials are wrong. Just checking these 2 items made problem solved and logging.properties was removed to avoid excessive logging.

Similar issue where increased verbosity helped with quick resolution was one that produced

org.apache.catalina.core.StandardContext start SEVERE: Error listenerStart
org.apache.catalina.core.StandardContext start SEVERE: Context [/grailswebapp] startup failed due to previous errors

In this case it was a ClassNotFoundException and problem has been solved after adding required class or jar.

Yet another example of unclear error message when JDK6 was used for application compiled with JDK7:

INFO: Deploying web application archive /home/tomcat/apache-tomcat-7.0.32/webapps/ROOT.war
Oct 13, 2012 8:03:33 AM org.apache.catalina.core.StandardContext startInternal
SEVERE: Error listenerStart
Oct 13, 2012 8:03:33 AM org.apache.catalina.core.StandardContext startInternal
SEVERE: Context [] startup failed due to previous errors

And after enabling verbose logging we know where we are (wrong JDK version used):

INFO: Deploying web application archive /home/tomcat/apache-tomcat-7.0.32/webapps/ROOT.war
Oct 13, 2012 8:05:19 AM org.apache.catalina.core.StandardContext listenerStart
SEVERE: Error configuring application listener of class website.web.MainAggregation
java.lang.UnsupportedClassVersionError: website/web/MainAggregation : Unsupported major.minor version 51.0 (unable to load class website.web.MainAggregation)

Refer Tomcat 7 documentation for more on logging.