[LOG4PHP-113] Milliseconds do not change when using LoggerLayoutPattern

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.0.0
• Fix Version/s: 2.1.0
• Component/s: Code
• Assignee: Unassigned
• Reporter: Ivan Habunek
• Created: 19/Apr/10 19:34
• Updated: 01/Dec/13 10:59
• Resolved: 27/Jul/10 13:50

Description

When using a LoggerLayoutPattern which has a date conversion pattern using milliseconds, the milliseconds are the same for all events. To reproduce, use the following code and configuration:

log4php.xml
===========
<?xml version='1.0' encoding='us-ascii'?>
<!DOCTYPE Library SYSTEM "log4php.dtd">

<log4php:configuration xmlns:log4php="http://logging.apache.org/log4php/" threshold="all" debug="false">
<appender name="default" class="LoggerAppenderEcho">
<layout class="LoggerLayoutPattern">
<param name="conversionPattern" value="%d

{Y-m-d H:i:s.u}

%m%n" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender_ref ref="default" />
</root>
</log4php:configuration>

PHP code:
=========
<?php

require '../log4php/src/main/php/Logger.php';
Logger::configure('log4php.xml');
$logger = Logger::getRootLogger();

foreach (range(0, 10) as $item)
{
$logger->debug("The time is: " . microtime(true));
usleep(10000);
}
?>

Example output:
==============
2010-04-19 20:57:52.318 The time is: 1271703472.3181
2010-04-19 20:57:52.318 The time is: 1271703472.3292
2010-04-19 20:57:52.318 The time is: 1271703472.3399
2010-04-19 20:57:52.318 The time is: 1271703472.3507
2010-04-19 20:57:52.318 The time is: 1271703472.3614

As you can see, the milliseconds are constant and equal to 318. This is the millisecond when the first event happened.

Expected output:
===============
2010-04-19 20:57:52.318 The time is: 1271703472.3181
2010-04-19 20:57:52.329 The time is: 1271703472.3292
2010-04-19 20:57:52.340 The time is: 1271703472.3399
2010-04-19 20:57:52.351 The time is: 1271703472.3507
2010-04-19 20:57:52.361 The time is: 1271703472.3614