Why is log4j not behaving as expected?

Question

I have a co-worker who is trying to get log4j to behave as follows:

• Log to Stdout
• By default, disable most output
• Show only messages from java.sql.PrepareStatement at level debug and up

He's getting caught up in the 'level' vs 'priority'. Here is his config file:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "D:/Java/apache-log4j-1.2.15/src/main/resources/org/apache/log4j/xml/log4j.dtd" >
<log4j:configuration> 

    <!--  Appenders -->
    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%5p %d{ISO8601} [%t][%x] %c - %m%n" />
        </layout>
    </appender>

    <!--  Loggers for ibatus and JDBC database -->
    <logger name="java.sql.PreparedStatement">
        <level value="debug"/>
    </logger>

    <!--  The Root Logger -->
    <root>
        <level value="error"/>
        <appender-ref ref="stdout"/>
    </root>

</log4j:configuration>

Simpler configuration as shown (Root Log Level = ERROR):

log4j: reset attribute= "false".
log4j: Threshold ="null".
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [java.sql.PreparedStatement] additivity to [true].
log4j: Level value for java.sql.PreparedStatement is  [debug].
log4j: java.sql.PreparedStatement level set to DEBUG
log4j: Level value for root is  [error].
log4j: root level set to ERROR
log4j: Class name: [org.apache.log4j.ConsoleAppender]
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%5p %d{ISO8601} [%t][%x] %c - %m%n].
log4j: Adding appender named [stdout] to category [root].

Configuration with Root Log Level changed to debug (replace queries with …)

log4j: reset attribute= "false".
log4j: Threshold ="null".
log4j: Retreiving an instance of org.apache.log4j.Logger.
log4j: Setting [java.sql.PreparedStatement] additivity to [true].
log4j: Level value for java.sql.PreparedStatement is  [debug].
log4j: java.sql.PreparedStatement level set to DEBUG
log4j: Level value for root is  [debug].
log4j: root level set to DEBUG
log4j: Class name: [org.apache.log4j.ConsoleAppender]
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%5p %d{ISO8601} [%t][%x] %c - %m%n].
log4j: Adding appender named [stdout] to category [root].
DEBUG 2010-03-19 12:59:58,256 [main][] com.ibatis.common.jdbc.SimpleDataSource - Created connection 1309601.
DEBUG 2010-03-19 12:59:58,256 [main][] java.sql.Connection - {conn-100000} Connection
DEBUG 2010-03-19 12:59:58,256 [main][] java.sql.Connection - {conn-100000} Preparing Statement:      …
DEBUG 2010-03-19 12:59:58,287 [main][] java.sql.PreparedStatement - {pstm-100001} Executing Statement:      …
DEBUG 2010-03-19 12:59:58,287 [main][] java.sql.PreparedStatement - {pstm-100001} Parameters: [%ATL]
DEBUG 2010-03-19 12:59:58,287 [main][] java.sql.PreparedStatement - {pstm-100001} Types: [java.lang.String]
DEBUG 2010-03-19 12:59:58,366 [main][] java.sql.ResultSet - {rset-100002} ResultSet
DEBUG 2010-03-19 12:59:58,381 [main][] java.sql.ResultSet - {rset-100002} Header: …
DEBUG 2010-03-19 12:59:58,381 [main][] java.sql.ResultSet - {rset-100002} Result: …
DEBUG 2010-03-19 12:59:58,381 [main][] java.sql.ResultSet - {rset-100002} Result: …
DEBUG 2010-03-19 12:59:58,381 [main][] java.sql.ResultSet - {rset-100002} Result: …
DEBUG 2010-03-19 12:59:58,397 [main][] com.ibatis.common.jdbc.SimpleDataSource - Returned connection 1309601 to pool.

How does he need to change his log4j.xml config file to make it behave as he's expecting?

Answer 1

I think the reason there are no log messages is that code you want to see logs from, doesn't use java.sql.PrepareStatement logger, but different loggers. Loggers are usually (although not necessarilly) named after classes that use them. I.e. com.ibatis.SomeClass would typically not use java.sql.PrepareStatement logger.

Set your root logger to DEBUG, and check out names of loggers that give you messages you want. Then configure these loggers with DEBUG and let root log at ERROR level only.

Btw, it's Prepare_d_Statement, it is interface (i.e. no logging code there), and it definitely doesn't use log4j since it is in JDK.

Answer 2

Insert the following addition into your log4j.xml:

<!-- *******************************************************
     WARNING: iBatus 2.3.3 (only ver. tested) is a little weird. 
             YOU MUST SET
             java.sql.Connection to debug to get any 
             java.sql.PreparedStatement debug logs.
     ************************************************************** -->       
<logger name="java.sql.Connection" additivity="false">
    <level value="debug"/>
</logger>

DEBUG 2010-03-19 14:27:08,425 [main][][java.sql.PreparedStatement] - {pstm-100001} Executing Statement:
...