New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Zend\Stdlib\ErrorHandler breaks custom error handlers #7497

Closed
lukasclausen opened this Issue May 7, 2015 · 8 comments

Comments

Projects
None yet
5 participants
@lukasclausen

lukasclausen commented May 7, 2015

I know this issue has already been discussed, but it still exists. The Logger error handler only works for the first triggered error:

$logger = new Zend\Log\Logger();
$streamOrUrl = array('stream' => 'php://stdout');
$writer = new Zend\Log\Writer\Stream($streamOrUrl);
$logger->addWriter($writer);
Zend\Log\Logger::registerErrorHandler($logger);

trigger_error('Some notice');
trigger_error('Some other notice');

The second notice will not be logged. That's because of the Zend\Stdlib\ErroHandler::start/stop() call in the log writers. I know this error handler calls are there for good reason, but they break the main custom error handler. In more detail the nested set_error_handler calls inside Zend\Stdlib\ErroHandler breaks it. I found out that the second parameter of set_error_handler causes the error when used inside of an error_handler. I suppose that's a php bug. The following won't work for the second error:

$eh = function($level,$message) {
    $error_handler2 = function ($level,$message) {
        echo "Handle Error inside: $message \n";
    };
    set_error_handler($error_handler2,E_WARNING);
    echo "Handle Error: $message \n";
    strpos();
    restore_error_handler();
    return true;
};

 set_error_handler($eh);

 trigger_error('Some message',E_USER_NOTICE);
 trigger_error('Some other message',E_USER_NOTICE);

When changing set_error_handler($error_handler2,E_WARNING); to set_error_handler($error_handler2); the code works as expected. So removing the second argument of set_error_handler inside Zend\Stdlib\ErroHandler start for me also fixes my logger error handler problems. Is there a reason why Zend\Stdlib\ErroHandler::start is limited to E_WARNINGS by default?

@weierophinney

This comment has been minimized.

Show comment
Hide comment
@weierophinney

weierophinney May 8, 2015

Member

Is there a reason why Zend\Stdlib\ErroHandler::start is limited to E_WARNINGS by default?

Yes: because it's the most common use case.

ErrorHandler is used primarily within the framework in order to detect conditions that would prevent operations from success while preventing emission of the error. Typically, these are due to PHP internal function failures (e.g., fopen()), which typically will return a boolean false but also emit a E_WARNING. As such, ErrorHandler::start() defaults to passing E_WARNING in the $error_types flag, so that the developer does not have to explicitly pass it. Only if a different mask is desired does the developer need to pass an argument to start().

The specific problem you're seeing is due to the default behavior of Zend\Log\Logger::registerErrorHandler(). Let's recap:

The Logger error handler only works for the first triggered error:

By default, the error handler we register is using set_error_handler(), but not passing the second $error_types argument; in other words, Zend\Stdlib\ErrorHandler is not even in use here. So, why is only the first error triggering?

Let's look at the signature:

public static function registerErrorHandler(Logger $logger, $continueNativeHandler = false)

That second argument is a flag that determines the return value from the handler. Internally, we do this:

return !$continueNativeHandler;

The way PHP works, it only invokes other registered error handlers if the return value is boolean false:

If the function returns FALSE then the normal error handler continues. (http://php.net/set_error_handler)

So, by default, we return boolean true, which means subsequent error handlers are not triggered. Therefore, to get the behavior you want, you need to pass a boolean true value as the second argument to that method when you register it.

One point: If you are constructing Zend\Log\Logger and registering the error handler using configuration (i.e., the errorhandler configuration option), the error handler is registered with the default value. As such, you cannot get the behavior you desire if you do this via configuration. One option you have is to create a delegator factory for your logger instance, and have it do the following inside:

$logger = $callback();
\Zend\Log\Logger::registerErrorHandler($logger, true);
return $logger;
Member

weierophinney commented May 8, 2015

Is there a reason why Zend\Stdlib\ErroHandler::start is limited to E_WARNINGS by default?

Yes: because it's the most common use case.

ErrorHandler is used primarily within the framework in order to detect conditions that would prevent operations from success while preventing emission of the error. Typically, these are due to PHP internal function failures (e.g., fopen()), which typically will return a boolean false but also emit a E_WARNING. As such, ErrorHandler::start() defaults to passing E_WARNING in the $error_types flag, so that the developer does not have to explicitly pass it. Only if a different mask is desired does the developer need to pass an argument to start().

The specific problem you're seeing is due to the default behavior of Zend\Log\Logger::registerErrorHandler(). Let's recap:

The Logger error handler only works for the first triggered error:

By default, the error handler we register is using set_error_handler(), but not passing the second $error_types argument; in other words, Zend\Stdlib\ErrorHandler is not even in use here. So, why is only the first error triggering?

Let's look at the signature:

public static function registerErrorHandler(Logger $logger, $continueNativeHandler = false)

That second argument is a flag that determines the return value from the handler. Internally, we do this:

return !$continueNativeHandler;

The way PHP works, it only invokes other registered error handlers if the return value is boolean false:

If the function returns FALSE then the normal error handler continues. (http://php.net/set_error_handler)

So, by default, we return boolean true, which means subsequent error handlers are not triggered. Therefore, to get the behavior you want, you need to pass a boolean true value as the second argument to that method when you register it.

One point: If you are constructing Zend\Log\Logger and registering the error handler using configuration (i.e., the errorhandler configuration option), the error handler is registered with the default value. As such, you cannot get the behavior you desire if you do this via configuration. One option you have is to create a delegator factory for your logger instance, and have it do the following inside:

$logger = $callback();
\Zend\Log\Logger::registerErrorHandler($logger, true);
return $logger;
@lukasclausen

This comment has been minimized.

Show comment
Hide comment
@lukasclausen

lukasclausen May 8, 2015

Thank you for your answer. Maybe I wasn’t clear enough. I created my own error handler which makes use of the Logger and this error handler is only called for the first error. My error handler is very similar to the Logger error handler.
When I use the Logger error handler I have the same result.
What I do:

$logger = new Zend\Log\Logger();
$streamOrUrl = array('stream' => 'php://stdout');
$writer = new Zend\Log\Writer\Stream($streamOrUrl);
$logger->addWriter($writer);
Zend\Log\Logger::registerErrorHandler($logger, false);

trigger_error('Some notice');
trigger_error('Some other notice');

The output I expect:

2015-05-08T21:49:05+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}
2015-05-08T21:49:05+02:00 NOTICE (5): Some other notice {"errno":1024,"file":"C:\\...\\index.php","line":39}

The output I get:

2015-05-08T21:50:25+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}

Notice: Some other notice in C:\...\index.php on line 39
Call Stack:
    0.0000     127472   1. {main}() C:\...\index.php:0
    0.0140     568128   2. trigger_error() C:\...\index.php:39

When I change Zend\Log\Logger::registerErrorHandler($logger, false); to Zend\Log\Logger::registerErrorHandler($logger, true); I get:

2015-05-08T21:54:51+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}

Notice: Some notice in C:\...\index.php on line 38
Call Stack:
    0.0005     127472   1. {main}() C:\...\index.php:0
    0.0130     567160   2. trigger_error() C:\...\index.php:38

Notice: Some other notice in C:\...\index.php on line 39
Call Stack:
    0.0005     127472   1. {main}() C:\...\index.php:0
    0.0235     568272   2. trigger_error() C:\...\index.php:39

Zf 2.4, php 5.5 / 5.6 tested on win7 and ubuntu

Whatever I do the Logger only logs the first error. In fact the Logger error handler is not even called for the second error but the native error handler is called.
So what normally happens if the Logger error handler is called as far as I know:

  1. Logger::log is called
  2. Logger goes through all writers and calls the write method
  3. Inside AbstractWriter::write normally Stdlib\ErrorHandler::start is called
  4. Stdlib\ErrorHandler::start registers a new error handler
  5. Log is written
  6. Stdlib\ErrorHandler::stop restores the former error handler which should be the closure defined in Logger::registerErrorHandler but it isn’t!

I suppose that’s because of some strange behaviour of set_error_handler and restore_error_handler, when the optional second parameter is used. When I modify the Zend\Stdlib\ErrorHandler:

-    public static function start($errorLevel = \E_WARNING)
+    public static function start()
     {
         if (!static::$stack) {
-            set_error_handler(array(get_called_class(), 'addError'),$errorLevel);
+            set_error_handler(array(get_called_class(), 'addError'));
         }

I get my expected result:

2015-05-08T21:49:05+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}
2015-05-08T21:49:05+02:00 NOTICE (5): Some other notice {"errno":1024,"file":"C:\\...\\index.php","line":39}

By removing the $errorLevel the former error handler is later restored correctly. I really don’t know why it doesn’t work with $errorLevel. It should but it doesn’t.

lukasclausen commented May 8, 2015

Thank you for your answer. Maybe I wasn’t clear enough. I created my own error handler which makes use of the Logger and this error handler is only called for the first error. My error handler is very similar to the Logger error handler.
When I use the Logger error handler I have the same result.
What I do:

$logger = new Zend\Log\Logger();
$streamOrUrl = array('stream' => 'php://stdout');
$writer = new Zend\Log\Writer\Stream($streamOrUrl);
$logger->addWriter($writer);
Zend\Log\Logger::registerErrorHandler($logger, false);

trigger_error('Some notice');
trigger_error('Some other notice');

The output I expect:

2015-05-08T21:49:05+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}
2015-05-08T21:49:05+02:00 NOTICE (5): Some other notice {"errno":1024,"file":"C:\\...\\index.php","line":39}

The output I get:

2015-05-08T21:50:25+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}

Notice: Some other notice in C:\...\index.php on line 39
Call Stack:
    0.0000     127472   1. {main}() C:\...\index.php:0
    0.0140     568128   2. trigger_error() C:\...\index.php:39

When I change Zend\Log\Logger::registerErrorHandler($logger, false); to Zend\Log\Logger::registerErrorHandler($logger, true); I get:

2015-05-08T21:54:51+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}

Notice: Some notice in C:\...\index.php on line 38
Call Stack:
    0.0005     127472   1. {main}() C:\...\index.php:0
    0.0130     567160   2. trigger_error() C:\...\index.php:38

Notice: Some other notice in C:\...\index.php on line 39
Call Stack:
    0.0005     127472   1. {main}() C:\...\index.php:0
    0.0235     568272   2. trigger_error() C:\...\index.php:39

Zf 2.4, php 5.5 / 5.6 tested on win7 and ubuntu

Whatever I do the Logger only logs the first error. In fact the Logger error handler is not even called for the second error but the native error handler is called.
So what normally happens if the Logger error handler is called as far as I know:

  1. Logger::log is called
  2. Logger goes through all writers and calls the write method
  3. Inside AbstractWriter::write normally Stdlib\ErrorHandler::start is called
  4. Stdlib\ErrorHandler::start registers a new error handler
  5. Log is written
  6. Stdlib\ErrorHandler::stop restores the former error handler which should be the closure defined in Logger::registerErrorHandler but it isn’t!

I suppose that’s because of some strange behaviour of set_error_handler and restore_error_handler, when the optional second parameter is used. When I modify the Zend\Stdlib\ErrorHandler:

-    public static function start($errorLevel = \E_WARNING)
+    public static function start()
     {
         if (!static::$stack) {
-            set_error_handler(array(get_called_class(), 'addError'),$errorLevel);
+            set_error_handler(array(get_called_class(), 'addError'));
         }

I get my expected result:

2015-05-08T21:49:05+02:00 NOTICE (5): Some notice {"errno":1024,"file":"C:\\...\\index.php","line":38}
2015-05-08T21:49:05+02:00 NOTICE (5): Some other notice {"errno":1024,"file":"C:\\...\\index.php","line":39}

By removing the $errorLevel the former error handler is later restored correctly. I really don’t know why it doesn’t work with $errorLevel. It should but it doesn’t.

@weierophinney

This comment has been minimized.

Show comment
Hide comment
@weierophinney

weierophinney May 11, 2015

Member

That sounds like a PHP bug, then. It's always best to specify the error level when calling set_error_handler() to ensure it only triggers when errors of a specific priority are issued. If restore_error_handler() is not popping it off correctly, that's a bug in the PHP engine.

Member

weierophinney commented May 11, 2015

That sounds like a PHP bug, then. It's always best to specify the error level when calling set_error_handler() to ensure it only triggers when errors of a specific priority are issued. If restore_error_handler() is not popping it off correctly, that's a bug in the PHP engine.

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Jan 11, 2016

@lukasclausen I was pointed out to this issue and I tried to reproduce your issue with as less code as possible. See e.g. https://3v4l.org/JdWWp
But I fail to reproduce the bug there. Can you manage to write such a script? Can you reproduce this with xdebug disabled/enabled?

nicolas-grekas commented Jan 11, 2016

@lukasclausen I was pointed out to this issue and I tried to reproduce your issue with as less code as possible. See e.g. https://3v4l.org/JdWWp
But I fail to reproduce the bug there. Can you manage to write such a script? Can you reproduce this with xdebug disabled/enabled?

@lukasclausen

This comment has been minimized.

Show comment
Hide comment
@lukasclausen

lukasclausen Jan 12, 2016

See for an example https://3v4l.org/6hW5O
Seems to work with hhvm.

The bug occurs when you have a nested error handler which is registered inside the current error handler and unregisterd before the original error handler finishes. It only occurs if the nested error handler is set for specific error types. The error handler the falls back to the php default error handler.

If the nested error handler is not limited (line 12) everythings fine:
https://3v4l.org/safbF

As a workaround I reset the main error handler at the end of each call:
https://3v4l.org/YijHT

I can reproduce it with both xdebug enabled and disabled.

lukasclausen commented Jan 12, 2016

See for an example https://3v4l.org/6hW5O
Seems to work with hhvm.

The bug occurs when you have a nested error handler which is registered inside the current error handler and unregisterd before the original error handler finishes. It only occurs if the nested error handler is set for specific error types. The error handler the falls back to the php default error handler.

If the nested error handler is not limited (line 12) everythings fine:
https://3v4l.org/safbF

As a workaround I reset the main error handler at the end of each call:
https://3v4l.org/YijHT

I can reproduce it with both xdebug enabled and disabled.

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Jan 12, 2016

Understood, thanks for the explanations.
This is https://bugs.php.net/63206 then

nicolas-grekas commented Jan 12, 2016

Understood, thanks for the explanations.
This is https://bugs.php.net/63206 then

@unhawkable

This comment has been minimized.

Show comment
Hide comment
@unhawkable

unhawkable May 5, 2017

Okay, but the bug has not been fixed since then.

unhawkable commented May 5, 2017

Okay, but the bug has not been fixed since then.

@Ocramius

This comment has been minimized.

Show comment
Hide comment
@Ocramius

Ocramius May 5, 2017

Member
Member

Ocramius commented May 5, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment