log4php is anti-intuitive (was not honouring logger levels)

Question

I am trying to use log4php and having a problems understanding the configuration, I am comparing the behaviour from a log4j xml to a log4php xml that are the same. The same code. But with different outputs. From the documentation I would expect 5 lines to be logged, but in the log4php, only one is. Please, I am driving myself crazy.

PHP code:

<?php

include("log4php/Logger.php");

Logger::configure('log4php.xml');

$rlogger = Logger::getRootLogger();
$rlogger->debug('Not logged');
$rlogger->error('Logged');

$logger = Logger::getLogger('com.suri');
$logger->debug('Logged');
$logger->warn('Logged');

$logger = Logger::getLogger('com.suri.factory');
$logger->debug('Not logged');
$logger->warn('Logged');

$logger = Logger::getLogger('com.suri.factory.Bar');
$logger->debug('Not logged');
$logger->info('Logged');

?>

XML config:

<?xml version="1.0" encoding="UTF-8" ?>
<configuration xmlns="http://logging.apache.org/log4php/">
  <!-- A1 is set to be a ConsoleAppender -->
  <appender name="A1" class="LoggerAppenderConsole">
    <layout class="LoggerLayoutPattern">
      <param name="ConversionPattern" value="%d [%t] - %-5p %c - %m%n"/>
    </layout>
  </appender>

  <logger name="com.suri.factory.Bar">
    <level value="info"/>
  </logger>
  <logger name="com.suri.factory">
    <level value="warn"/>
  </logger>

  <logger name="com">
    <level value="debug"/>
  </logger>

  <root>
    <level value="error" />
    <appender-ref ref="A1" />
  </root>

</configuration>

Output:

2014-03-13T18:01:30-03:00 [14939] - ERROR root - Logged

Expected Output (generated with same config & same code in jython+log4j):

2014-03-13 18:09:03,591 [main] - ERROR root - Logged
2014-03-13 18:09:03,592 [main] - DEBUG com.suri - Logged
2014-03-13 18:09:03,592 [main] - WARN  com.suri - Logged
2014-03-13 18:09:03,592 [main] - WARN  com.suri.factory - Logged
2014-03-13 18:09:03,592 [main] - INFO  com.suri.factory.Bar - Logged

jython code:

from org.apache.log4j import *
from org.apache.log4j.xml import *


if __name__ == '__main__':
    xml.DOMConfigurator.configure('log4j.xml')
    rlogger = LogManager.getRootLogger()
    rlogger.debug('Not logged');
    rlogger.error('Logged');

    logger = LogManager.getLogger('com.suri');
    logger.debug('Logged');
    logger.warn('Logged');

    logger = LogManager.getLogger('com.suri.factory');
    logger.debug('Not logged');
    logger.warn('Logged');

    logger = LogManager.getLogger('com.suri.factory.Bar');
    logger.debug('Not logged');
    logger.info('Logged');

Jython XML config:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
  <!-- A1 is set to be a ConsoleAppender -->
  <appender name="A1" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d [%t] - %-5p %c - %m%n"/> 
    </layout> 
  </appender>

  <logger name="com.suri.factory.Bar">
    <level value="info"/> 
  </logger>
  <logger name="com.suri.factory">
    <level value="warn"/>
  </logger>

  <logger name="com">
    <level value="debug"/>
  </logger>

  <root>
     <level value="error" />
    <appender-ref ref="A1" /> 
  </root>

</log4j:configuration>

Thanks!

Answer 1

The way it is currently configured, Log4PHP will not log anything below error level. This is because any configured logger (which should be seen as a log message entry point) is passing only the messages that are equal or above it's configured threshold, and only the root logger does in fact have an appender configured, to which it will only log if the log message level is above IT'S threshold (i.e. any message that is below ERROR level will not get logged).

You can work around it by adding appenders to every available logger you want to configure. That way, this logger by itself will try to write the message to the appender, and additionally will pass it up the chain. Note that this might lead to messages being written twice if the threshold of a parent logger is equal or less that the original logger. To avoid passing the messages upstream, you'd use the additivity="false" attribute.

Note that you can in fact use the same appender multiple times for all loggers to be able to only configure it once, but log all the different levels of messages depending on how the actual logger is being configured.

Also note that Log4PHP is a different product than log4j - while they look similar, the developers do not necessarily interact with each other, and supporting the same configuration format with the same features being enabled in the same way probably wasn't on their roadmap. Which actually is a good thing for each individual project because it would be a hard restriction to additionally support configuration decisions made by a completely different team.

So in the end, I'd suggest you this configuration:

<?xml version="1.0" encoding="UTF-8" ?>
<configuration xmlns="http://logging.apache.org/log4php/">
  <!-- A1 is set to be a ConsoleAppender -->
  <appender name="A1" class="LoggerAppenderConsole">
    <layout class="LoggerLayoutPattern">
      <param name="ConversionPattern" value="%d [%t] - %-5p %c - %m%n"/>
    </layout>
  </appender>

  <logger name="com.suri.factory.Bar" additivity="false">
    <level value="info"/>
    <appender-ref ref="A1" />
  </logger>
  <logger name="com.suri.factory" additivity="false">
    <level value="warn"/>
    <appender-ref ref="A1" />
  </logger>

  <logger name="com" additivity="false">
    <level value="debug"/>
    <appender-ref ref="A1" />
  </logger>

  <root>
    <level value="error" />
    <appender-ref ref="A1" />
  </root>

</configuration>

It would be even better if you could avoid using XML as the configuration source, but use a PHP array configuration instead, because you'd avoid having to parse XML on every request, but PHP would be able to cache the configuration file (which is PHP code) in it's opcode cache. To get the PHP array representing your current XML configuration, you can dump the result like this:

$configurator = new LoggerConfiguratorDefault();
$config = $configurator->parse('/path/to/config.xml');
var_export($config); // prints to stdout

Answer 2

you set threshold level to highest (in your case it is error) so the lower level will not be logged by this logger.read Logger threshold here.

change following in your xml config file:

<root>
  <level value="TRACE" />
  <appender-ref ref="A1" />
</root>

see the different level of threshold here.

According to log4php:

A logger can be assigned a threshold level. All logging requests with level lower than this threshold will be ignored.

For example, setting logger threshold to INFO means that logging requests with levels TRACE and DEBUG will not be logged by this logger.

Hope it is useful for you.