I am implementing a custom error handler and started noticing some bizarre
behavior. Every Nth time I refresh the page, I see the error/output.
In my 'includes/common.inc.php' the key things are these:
set_error_handler('php_error_handler');
function php_error_handler($errno, $errstr, ...)
{
//does some stuff
//calls php_custom_error_log()
}
function php_custom_error_log()
{
echo "php_custom_error_log : ".date('H:i:s');
if ($error = error_get_last())
{
var_dump(LOG_LEVEL, $error);
//does more stuff
}
My test page:
<?php
define('LOG_LEVEL', E_ALL ^ E_NOTICE);
error_reporting(LOG_LEVEL);
ini_set('display_errors','On');
define('VM', true);
define('DEVELOPMENT', false);
ini_set('xdebug.var_display_max_children', 1000 );
ini_set('xdebug.var_display_max_depth', 5 );
require_once 'includes/common.inc.php';
###### BEGIN TEST #########
foreach($empty as $k) echo $k;
?>
For those astute observers, you'll note that $empty is not an array and
therefore I expect an error message (well warning)
( ! ) Warning: Invalid argument supplied for foreach() in
/usr/home/vz/examples.videosz.com/error_handler_tests.php on line 20
Call Stack
# Time Memory Function Location
1 0.0005 663616 {main}( ) ../error_handler_tests.php:0
As I simply click 'refresh' on the browser I noticed that it was only
periodically working. I then deduced that it was directly related to the
number of apache threads. So if I had 15 then it would work every 15th
refresh:
developer@vm:/usr/local/etc/apache22$ ps aux | grep httpd
(standard input):39:root 15855 0.0 2.0 204156 20292 ?? Ss 28Feb12
1:33.48 /usr/local/sbin/httpd -k start
(standard input):48:www 89522 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):49:www 89523 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):50:www 89524 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):51:www 89525 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):52:www 89527 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):53:www 89528 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):54:www 89529 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):55:www 89530 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):56:www 89531 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):57:www 89532 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):58:www 89533 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):59:www 89534 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):60:www 89535 0.0 2.0 204156 20332 ?? I 8:03PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):61:www 89563 0.0 2.1 206204 21700 ?? I 8:17PM
0:00.10 /usr/local/sbin/httpd -k start
(standard input):62:www 89578 0.0 2.0 204156 20332 ?? I 8:22PM
0:00.01 /usr/local/sbin/httpd -k start
(standard input):74:developer 89587 0.0 0.1 9092 1196 1 S+ 8:30PM
0:00.01 grep -inH --color httpd
124 <IfModule prefork.c>
125 StartServers 15
126 MinSpareServers 15
127 MaxSpareServers 20
128 ServerLimit 50
129 MaxClients 50
130 MaxRequestsPerChild 15
131 KeepAlive Off
132 </IfModule>
Just to check and the time is updating each press and every 15th try I'd get
this:
php_custom_error_log : 19:54:20
int 30711
array
'type' => int 8192
'message' => string 'Directive 'register_globals' is deprecated in PHP 5.3
and greater' (length=65)
'file' => string 'Unknown' (length=7)
'line' => int 0
When I'd expect to see a message every time (with a new timestamp).
Then I REALLY looked at the 'message' part. "register_globals". WTF? That
isn't the error I expected.
Hmmm.. what happens if I move the second function inline to the first...
BAM! EVERY TIME it works perfectly.
So WTFF??! Why does moving it inline make any difference? All I suspect is
the $error = error_get_last() part. For some reason that isn't consistent.
And the other strange thing is that it's giving me erroneous error messages
(well, we do have register_globals on, but that's not the error I was
expecting).
Then I did another test replacing the foreach() with this statement:
require_once "/foo.inc.php";
A few bizarre things about this too. For starters why do I get TWO error
messages. One WARNING from MY error handler and then a FATAL default PHP
one?! Sorta defeats my purpose.
WARNING: require_once(/foo.inc.php) [function.require-once]:
failed to open stream: No such file or directory in
/usr/home/vz/examples.com/error_handler_tests.php on line
22
Fatal error: require_once() [function.require]:
Failed opening required '/foo.inc.php'
(include_path='.:/home/SHARED')
in /usr/home/examples. com/error_handler_tests.php on line
22
Next if I print out php_error_handler($errno, ...) it says "2". And '2' is a
WARNING according to this page:
http://php.net/manual/en/errorfunc.constants.php Shouldn't it be "1"!?
developer@vm_daevid:/usr/local/etc/apache22$ php --version
PHP 5.3.6 with Suhosin-Patch (cli) (built: Apr 28 2011 14:20:48)
Copyright (c) 1997-2011 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2011 Zend Technologies
with Xdebug v2.0.5, Copyright (c) 2002-2008, by Derick Rethans
Running on FreeBSD.
--
PHP General Mailing List (http://www.php.net/)
To unsubscribe, visit: http://www.php.net/unsub.php
