Tomcat catalina.out file is growing very rapidly! How to prevent Hibernate's INFO and DEBUG statements from getting added to catalina.out file?

Question

My Java application (Spring, Hibernate, MySQL) is running in Tomcat 5.5

After the last set of changes to my application, Tomcat's catalina.out file is growing very rapidly. With each query it adds a few MBs of INFO and DEBUG statements to the file

The log file has very large number of INFO and DEBUG statements such as the following:

01:52:45.412 [main] INFO  o.hibernate.cfg.annotations.Version - Hibernate Annotations 3.5.6-Final
01:52:45.465 [main] INFO  org.hibernate.cfg.Environment - Hibernate 3.5.6-Final
01:52:45.468 [main] INFO  org.hibernate.cfg.Environment - hibernate.properties not found
01:52:45.473 [main] INFO  org.hibernate.cfg.Environment - Bytecode provider name : javassist
01:52:45.479 [main] INFO  org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling
01:52:45.629 [main] DEBUG o.h.i.f.DefaultIdentifierGeneratorFactory - Registering IdentifierGenerator strategy [uuid] -> [class org.hibernate.id.UUIDHexGenerator]
01:52:45.635 [main] DEBUG o.h.i.f.DefaultIdentifierGeneratorFactory - Registering IdentifierGenerator strategy [hilo] -> [class org.hibernate.id.TableHiLoGenerator]
01:52:45.636 [main] DEBUG o.h.i.f.DefaultIdentifierGeneratorFactory - Registering IdentifierGenerator strategy [assigned] -> [class org.hibernate.id.Assigned]
01:52:45.639 [main] DEBUG o.h.i.f.DefaultIdentifierGeneratorFactory - Registering IdentifierGenerator strategy [identity] -> [class org.hibernate.id.IdentityGenerator]
01:52:45.640 [main] DEBUG o.h.i.f.DefaultIdentifierGeneratorFactory - Registering IdentifierGenerator strategy [select] -> [class org.hibernate.id.SelectGenerator]


01:52:45.668 [main] INFO  o.h.annotations.common.Version - Hibernate Commons Annotations 3.2.0.Final
01:52:45.719 [main] DEBUG o.h.cfg.AnnotationConfiguration - Execute first pass mapping processing
01:52:45.780 [main] DEBUG o.h.cfg.AnnotationConfiguration - Process hbm files
01:52:45.780 [main] DEBUG o.h.cfg.AnnotationConfiguration - Process annotated classes
01:52:45.791 [main] INFO  org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: com.knownomy.scl.appcommon.domain.Language
01:52:45.805 [main] INFO  o.h.cfg.annotations.QueryBinder - Binding Named query: language.id => from Language language where language.id = ?
01:52:45.821 [main] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3DiscriminatorColumn{logicalColumnName'DTYPE', discriminatorTypeName='string'}
01:52:45.824 [main] DEBUG org.hibernate.cfg.AnnotationBinder - no value specified for 'javax.persistence.sharedCache.mode'; using UNSPECIFIED
01:52:45.843 [main] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name Language
01:52:45.849 [main] INFO  o.h.cfg.annotations.EntityBinder - Bind entity com.knownomy.scl.appcommon.domain.Language on table language

01:52:50.164 [main] DEBUG o.h.hql.ast.QueryTranslatorImpl - parse() - HQL: from com.knownomy.scl.quiz.domain.Question question where question.chapter.id=? and question.questionSource.id=? and question.mcq.questionText=?
01:52:50.177 [main] DEBUG org.hibernate.hql.ast.AST - --- HQL AST ---
 \-[QUERY] Node: 'query'
    +-[SELECT_FROM] Node: 'SELECT_FROM'
    |  \-[FROM] Node: 'from'
    |     \-[RANGE] Node: 'RANGE'
    |        +-[DOT] Node: '.'
    |        |  +-[DOT] Node: '.'
    |        |  |  +-[DOT] Node: '.'
    |        |  |  |  +-[DOT] Node: '.'
    |        |  |  |  |  +-[DOT] Node: '.'
    |        |  |  |  |  |  +-[IDENT] Node: 'com'
    |        |  |  |  |  |  \-[IDENT] Node: 'knownomy'
    |        |  |  |  |  \-[IDENT] Node: 'scl'
    |        |  |  |  \-[IDENT] Node: 'quiz'
    |        |  |  \-[IDENT] Node: 'domain'
    |        |  \-[IDENT] Node: 'Question'
    |        \-[ALIAS] Node: 'question'
    \-[WHERE] Node: 'where'

Content of log4j.properties:

log4j.rootLogger=INFO, stdout, R

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=[%5p] %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n

log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=${catalina.home}/logs/SmartCloudLearningMobi.log
log4j.appender.R.MaxFileSize=10MB 
log4j.appender.R.MaxBackupIndex=10 
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=[%5p] %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n

log4j.logger.org.hibernate=ERROR, stdout, R
log4j.logger.org.hibernate.type=ERROR, stdout, R
log4j.logger.org.hibernate.SQL=ERROR, stdout, R
log4j.logger.org.hibernate.tool.hbm2ddl=ERROR, stdout, R
log4j.logger.org.hibernate.cache=ERROR, stdout, R
log4j.additivity.org.hibernate.SQL=false
log4j.logger.org.springframework=ERROR, stdout, R
log4j.logger.org.springframework.test.context.junit4.SpringJUnit4ClassRunner=ERROR, stdout, R

Content of application.properties file:

#  Application Properties
path.webinf=webapps/SmartCloudLearningMobi/WEB-INF
# JDBC Connection information
jdbc.driverClassName=com.mysql.jdbc.Driver
jdbc.url=jdbc:mysql://localhost:3306/databasename?useUnicode=true&characterEncoding=UTF8
jdbc.username=root
jdbc.password=mypassword
###hibernate
hibernate.show_sql=false
hibernate.format_sql=true
hibernate.transaction.factory_class=org.hibernate.transaction.JDBCTransactionFactory
hibernate.dialect=org.hibernate.dialect.MySQLDialect
hibernate.c3p0.min_size=1
hibernate.c3p0.max_size=25
hibernate.c3p0.acquire_increment=5
hibernate.c3p0.timeout=1800
hibernate.c3p0.max_statements=50
hibernate.c3p0.idle_test_period=3600

In the last change, I removed the following jar file:

ejb3-persistance.jar

and added the following jar files:

aspectjtools-1.5.4.jar
bval-core-0.3-incubating.jar
hibernate-validator-4.1.0.Final.jar
jackson-core-asl-1.6.4.jar
jackson-mapper-asl-1.6.4.jar
joda-time-1.6.2.jar
joda-time-jsptags-1.0.2.jar
jstl-1.2.jar
validation-api-1.0.0.GA.jar

Could someone tell me how to prevent Hibernate's INFO and DEBUG statements from getting added to catalina.out file? Much appreciated.

Update: Based on what I found on the web, I updated log4j.properties file to the following: log4j.rootLogger=INFO, stdout, R

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=[%5p] %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n
#log4j.appender.stdout.layout.ConversionPattern=[%5p] %t %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n

log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=${catalina.home}/logs/SmartCloudLearningMobi.log
log4j.appender.R.MaxFileSize=10MB 
log4j.appender.R.MaxBackupIndex=10 
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=[%5p] %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n
#log4j.appender.R.layout.ConversionPattern=[%5p] %t %d{yyyy-MM-dd HH:mm:ss} (%F:%M:%L) - %m%n

log4j.logger.org.hibernate=ERROR, stdout, R

### log HQL parse trees  
log4j.logger.org.hibernate.hql=ERROR, stdout, R

### Log HQL and SQL ASTs during query parsing ###  
log4j.logger.org.hibernate.hql.ast.AST=ERROR, stdout, R
log4j.additivity.org.hibernate.hql.ast.AST=false

### log just the SQL  
log4j.logger.org.hibernate.SQL=ERROR, stdout, R
log4j.additivity.org.hibernate.SQL=false

### log JDBC bind parameters. Very userfull, when debug parameterized queries ###  
log4j.logger.org.hibernate.type=ERROR, stdout, R
log4j.additivity.org.hibernate.type=false

### log schema export/update ###
log4j.logger.org.hibernate.tool.hbm2ddl=ERROR, stdout, R

### log cache activity ###
log4j.logger.org.hibernate.cache=ERROR, stdout, R

### log transaction activity  
log4j.logger.org.hibernate.transaction=ERROR, stdout, R

### Log all JDBC resource acquisition  
log4j.logger.org.hibernate.jdbc=ERROR, stdout, R

### enable the following line if you want to track down connection ###  
### leakages when using DriverManagerConnectionProvider ###  
log4j.logger.org.hibernate.connection.DriverManagerConnectionProvider=ERROR, stdout, R

log4j.logger.org.hibernate.cfg=ERROR, stdout, R


log4j.logger.org.springframework=ERROR, stdout, R
log4j.logger.org.springframework.test.context.junit4.SpringJUnit4ClassRunner=ERROR, stdout, R

But it made no difference! I still see the same log statements in catalina.out file! How can I solve this issue? Anyone?

Answer 1

I was having same issue and this is how I was able to fix with following steps:

1. Navigate to conf folder in tomcat director (the way I have tomcat setup, the location is /usr/local/tomcat/conf. This can be different for you depending on how tomcat is installed)
2. Edit logging.properties file (will need root access: vim sudo logging.properties or login as root using sudo su - and then do vim logging.properties)
3. Change
   .handlers = 1catalina.org.apache.juli.AsyncFileHandler, java.util.logging.ConsoleHandler
   to
   .handlers = 1catalina.org.apache.juli.AsyncFileHandler
4. Save and restart tomcat (/usr/local/tomcat/bin/shutdown.sh and then /usr/local/tomcat/bin/startup.sh)

I also noticed my tomcat log folder (/usr/local/tomcat/logs) was quite huge. To check the size of the log folder do the following du -hs /usr/local/tomcat/logs/. To resolve this, I setup a cron that would clean the files every night or you can run these commands manually. Here is the shell script that would delete files which are 5 days older

#!/bin/sh
find /usr/local/tomcat/logs -name 'catalina.*.log' -mtime +5 -print0 | xargs -0 rm -f
find /usr/local/tomcat/logs -name 'localhost_access_log.*.txt' -mtime +5 -print0 | xargs -0 rm -f

Answer 2

Whats most likely happening is that its not Log4j that is doing the logging. Its probably Tomcat's JULI logger that is. You should look at

http://tomcat.apache.org/tomcat-5.5-doc/logging.html

And make sure that log4j is setup correctly (ie so that it uses it instead of its default logging system)