Hibernate JPA EntityManager creates extra log4j appender?

Question

I've written a simple console app which uses JPA to connect to a MySQL database. The actual reading/writing of data is working, but logging seems to be screwed up. Each EntityManager instance that I create seems to add its own log4j appender to the console. So, since I have three EntityManager instances in my app, I get three extra lines in my console output in addition to the "real" console output line I want. Here's an example. The first line is from my "real" appender, the other three seem to be coming from the EntityManager's appender:

08:31:58,970 com.electricgearbox.app.ProcessDataItemApp DEBUG main foobar:169 - geoEntityDao.getByCompositeKey took 81 milliseconds 
0 [main] DEBUG foobar  - geoEntityDao.getByCompositeKey took 81 milliseconds 
0 [main] DEBUG foobar  - geoEntityDao.getByCompositeKey took 81 milliseconds 
0 [main] DEBUG foobar  - geoEntityDao.getByCompositeKey took 81 milliseconds

Here is my log4j configuration:

log4j.rootCategory=WARN, mylog

log4j.appender.mylog=org.apache.log4j.ConsoleAppender
log4j.appender.mylog.layout=org.apache.log4j.PatternLayout
log4j.appender.mylog.layout.ConversionPattern=%d{ABSOLUTE} %C %5p %t %c{2}:%L - %m%n

log4j.category.foobar=DEBUG

I would like to be able to turn off this behavior and just get the console lines I want. I don't seem to be able to "crack the code" on how to do that - any help would be appreciated...

Additional information: It appears that there are two things going on here. The first is the log4j appender additivity setting, which is true by default. Re-reading the sparse log4j documentation (http://logging.apache.org/log4j/1.2/manual.html) I came across this:

Each enabled logging request for a given logger will be forwarded to all the appenders in that logger as well as the appenders higher in the hierarchy.

What that does NOT mention is that it apparently will do this regardless of the setting of the loggers higher in the hierarchy.

What this means, or seems to mean in my case, was that although my root logger was set to WARN, the appenders attached to it by the Hibernate classes were still being used by DEBUG-level messages. This is the opposite of what I would expect to happen. I'm not sure if this represents a bug in the Hibernate 4.0.1 JPA implementation or just a lack of documentation on the part of log4j, or a glitch between log4j and slf4j (used by Hibernate).

The second thing that's going on is that every time you create an EntityManager object, it seems to add an appender to your log4j logging tree, so if you have multiple EntityManagers, you get multiple logging messages. This I'm pretty sure is a bug in the Hibernate logging.

Still looking for an explanation or an example of how this "additivity" works in practice with log4j - it seems to be working in the reverse of what I would expect from the limited documentation. That is, appenders seem to be passed DOWN the logging tree instead of logging events being passed UP.

Here is what I have so far for my (revised) log4j properties file, and it appears to be working:

log4j.rootCategory=WARN, mylog

# logger "root" logs at WARN level to appender "mylog"
log4j.appender.mylog=org.apache.log4j.ConsoleAppender
log4j.appender.mylog.layout=org.apache.log4j.PatternLayout

# Logger "foobar" logs at DEBUG level to appender "bootylog"
log4j.category.foobar=DEBUG, bootylog

log4j.appender.bootylog=org.apache.log4j.ConsoleAppender
log4j.appender.bootylog.layout=org.apache.log4j.PatternLayout
log4j.appender.bootylog.layout.ConversionPattern=%d{ABSOLUTE} %C %5p %t %c{2}:%L - %m%n

# additivity is off
log4j.additivity.foobar=false
log4j.additivity.org.hibernate=false

This gives me the following output, which is exactly what I want:

11:15:43,622 com.electricgearbox.app.ProcessDataItemApp DEBUG main foobar:152 - geoDataItemDao.create took 5 milliseconds 
11:15:43,624 com.electricgearbox.app.ProcessDataItemApp DEBUG main foobar:166 - geoEntityDao.getByCompositeKey took 2 milliseconds 
11:15:43,626 com.electricgearbox.app.ProcessDataItemApp DEBUG main foobar:159 - dataEntityDao.getDataEntityByFieldCode took 1 milliseconds

Finally, I highly recommend to anyone who is having problems with log4j that they turn on this command line option when they run their app:

-Dlog4j.debug

score 0 · Answer 1 · edited May 23 '17 at 11:56

0

As answered elsewhere, try to change the logging level for hibernate in your log4j properties

e.g.

log4j.logger.org.hibernate=info

edited May 23 '17 at 11:56

Community

1
1

answered May 06 '12 at 15:49

Eran Medan

44,555
61
184
276

1

This is not a duplicate of another issue. I am aware of how to set logging levels in log4j. I am asking why I am getting duplicate lines on the output. I tried googling various combinations of "log4j", "duplicate" and "EntityManager" for several hours before finally posting this question. – user1071914 May 06 '12 at 16:07
did the above not work for you? I don't think you can turn it completely off as the log4j properties of Hibernate is in your classpath as far as I know – Eran Medan May 06 '12 at 16:15
1

I narrowed it down to a problem with the log4j.additivity setting, which seems to work differently than the documentation led me to believe. I included the full details in my edited message above. – user1071914 May 06 '12 at 22:00
Thanks for posting the update with the solution! Just for clarity, I would consider moving it from the question body and adding it as an answer (and accepting it) – Eran Medan May 07 '12 at 00:26

score 0 · Accepted Answer · answered May 07 '12 at 14:16

It appears that there are two things going on here. The first is the log4j appender additivity setting, which is true by default. Re-reading the sparse log4j documentation (http://logging.apache.org/log4j/1.2/manual.html) I came across this: