Home » Logging » Log » Bug #9011

[2006-10-12 21:55 UTC] arne dot bippes at bippesbrandao dot de

Description:
------------
I have a Logging Class which adds a shutdown_function in its constructor.
Since I'm using several channels i use Log composite.
Currently the shutdown Function called every time i do some logging. It should only be called once!

The Bug seems to occur since Version 1.9.7 since in PEAR::Log Version 1.9.6 I'm getting the expected result.

Test script:
---------------
// Logging Class
class Log_bdowin extends Log
{
// Constructor
function Log_bdowin($name, $ident = '', $conf = array(), $level = PEAR_LOG_DEBUG)
{
// lots of code ... //
register_shutdown_function(array($this, 'open'));
}
// Shutdownfunction
function open()
{
echo "OPEN:";
echo "<" . microtime() . ">\n";
var_dump(debug_backtrace());
// a lot of code which does my logging output
return;

}
}
// My Main Script (shortened ...)
$Log = &Log::singleton('composite');
$Log_bdowin = &Log::singleton('bdowin', '', 'bdowin', $bdowin_conf, PEAR_LOG_DEBUG);
echo "<br>\n------------------MARKER1----------------------<br>\n";
$Log->addChild($Log_bdowin);
echo "<br>\n------------------MARKER2----------------------<br>\n";
$Log->log('+++++Dummy Logging+++++',PEAR_LOG_DEBUG);
echo "<br>\n------------------MARKER3----------------------<br>\n";
$Log->log('+++++Dummy Logging+++++',PEAR_LOG_DEBUG);
echo "<br>\n------------------MARKER4----------------------<br>\n";
exit;

Expected result:
----------------
------------------MARKER1----------------------

------------------MARKER2----------------------

------------------MARKER3----------------------

------------------MARKER4----------------------
OPEN:<0.82545900 1160689984> array(1) { [0]=> array(4) { ["function"]=> string(4) "open" ["class"]=> string(10) "log_bdowin" ["type"]=> string(2) "->" ["args"]=> array(0) { } } }

Actual result:
--------------
------------------MARKER1----------------------

------------------MARKER2----------------------
OPEN:<0.75105100 1160689255> array(3) { [0]=> array(6) { ["file"]=> string(63) "/home/arne/public_html/bdoproject/bdolib/pear/Log/composite.php" ["line"]=> int(63) ["function"]=> string(4) "open" ["class"]=> string(10) "log_bdowin" ["type"]=> string(2) "->" ["args"]=> array(0) { } } [1]=> array(6) { ["file"]=> string(63) "/home/arne/public_html/bdoproject/bdolib/pear/Log/composite.php" ["line"]=> int(144) ["function"]=> string(4) "open" ["class"]=> string(13) "log_composite" ["type"]=> string(2) "->" ["args"]=> array(0) { } } [2]=> array(6) { ["file"]=> string(43) "/home/arne/public_html/bdoproject/index.php" ["line"]=> int(88) ["function"]=> string(3) "log" ["class"]=> string(13) "log_composite" ["type"]=> string(2) "->" ["args"]=> array(2) { [0]=> &string(38) "++++++++++++++++++++++++++++++++++++++" [1]=> ∫(7) } } }
------------------MARKER3----------------------
OPEN:<0.75176400 1160689255> array(3) { [0]=> array(6) { ["file"]=> string(63) "/home/arne/public_html/bdoproject/bdolib/pear/Log/composite.php" ["line"]=> int(63) ["function"]=> string(4) "open" ["class"]=> string(10) "log_bdowin" ["type"]=> string(2) "->" ["args"]=> array(0) { } } [1]=> array(6) { ["file"]=> string(63) "/home/arne/public_html/bdoproject/bdolib/pear/Log/composite.php" ["line"]=> int(144) ["function"]=> string(4) "open" ["class"]=> string(13) "log_composite" ["type"]=> string(2) "->" ["args"]=> array(0) { } } [2]=> array(6) { ["file"]=> string(43) "/home/arne/public_html/bdoproject/index.php" ["line"]=> int(90) ["function"]=> string(3) "log" ["class"]=> string(13) "log_composite" ["type"]=> string(2) "->" ["args"]=> array(2) { [0]=> &string(38) "++++++++++++++++++++++++++++++++++++++" [1]=> ∫(7) } } }
------------------MARKER4----------------------
OPEN:<0.75225000 1160689255> array(1) { [0]=> array(4) { ["function"]=> string(4) "open" ["class"]=> string(10) "log_bdowin" ["type"]=> string(2) "->" ["args"]=> array(0) { } } }

[2006-10-15 12:14 UTC] arne dot bippes at bippesbrandao dot de

I looked inside the Log_composite code which led me to the problem.
The function i wanted to be called on shutdown was named "open". "open" is used by Log_composite to check wheter the Logging class is instanciated (better "openend") correctly. Since my function didn't return a boolean true . It was called again every time I did a logging request.
Changing the function to another name resolved the problem.

The "bug" was my improper use of the Log-Class, which started showing in Version 1.9.7, so please feel free to close it. Thank you for your Feedback!

[2006-10-15 12:17 UTC] arne dot bippes at bippesbrandao dot de

... able to close it by myself.