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!

score 1 · Accepted Answer · answered Mar 31 '14 at 18:40

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

I understand. I consider this to be a correct answer to my question. I think the way log4php is designed is flawed then, it should try to mimick as much as possible log4j, otherwise change the name. Also, I feel the documentation is missleading and the way it is implemented calls for much more configuration (all the additivity). Thanks! — Javier, Apr 08 '14 at 17:41

score 0 · Answer 2 · edited Jun 20 '20 at 09:12

0

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.

edited Jun 20 '20 at 09:12

Community

1
1

answered Mar 22 '14 at 06:51

DS9

2,995
4
52
102

This is not a solution. Lowering the root level only makes it log *every* message. Check the code, it will log messages that should not be. Also, i belive there is an implementation error in log4php.Why whould it work differently for the same configuration? – Javier Mar 25 '14 at 15:02
Sorry if I seemed blunt. But I find it very frustrating that both implementations work differently. – Javier Mar 25 '14 at 18:31
log4php produce this output `2014-03-13T18:01:30-03:00 [14939] - ERROR root - Logged` for your code, that is correct beacause your log level is set for `error`. see my updated answer. – DS9 Mar 26 '14 at 05:41
My main issue is that same config, same code in log4php and log4j yields different logs. Reading the docs I get the idea that, if I set a different logging threshold for a logger down the chain, logging with that logger should print the messages that are expected ('Logged' message in the code). Regards – Javier Mar 27 '14 at 14:07

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

2 Answers2