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?

Wildee

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

Fungistat

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)

Grahamgrahame

Adam, thanks for the suggestion. As I did more reading on logging, it seems I may need to add logging statements for the new jar files I added to the application, just as I have "log4j.logger.org.hibernate=ERROR, stdout, R" in log4j.properties to restrict logging level to ERROR for org.hibernate. Does it look like a decent angle to explore? – Wildee

If your going to write new code consider looking into slf4j as a logger. I have gotten Slf4j to work some of the most difficult platforms (websphere) so it should work with Tomcat 5.5. The other option you should consider is just upgrading to Tomcat 6 as it is very stable and does a better job logging. – Grahamgrahame

I added the following to log4j.properties but it made no difference! Now I'm going to look into JULI log4j.logger.org.hibernate.cfg=ERROR, stdout, R log4j.logger.org.hibernate.hql.ast=ERROR, stdout, R log4j.logger.o.h.cfg.annotations=ERROR, stdout, R log4j.logger.o.h.c.annotations=ERROR, stdout, R log4j.logger.o.h.hql.antlr=ERROR, stdout, R log4j.logger.o.hibernate.hql.ast.tree=ERROR, stdout, R – Wildee

The problem I am facing here is similar, but happening only on CentOS 7.6. Same tomcat package works well on CentOS 6 where catalina.out file does not show up http logs. Do you know what could be wrong with CentOS 7.6? – Bludgeon