ZF-11161: RegisterErrorHandle not work with Xml formatter

Issue Type: Bug Created: 2011-03-10T19:20:10.000+0000 Last Updated: 2011-07-13T18:23:42.000+0000 Status: Resolved Fix version(s): - 1.11.9 (14/Jul/11)

Reporter: Fabio Ginzel (fabioginzel) Assignee: Matthew Weier O'Phinney (matthew) Tags: - Zend_Log

Related issues: Attachments:


If I call the Registererrorhandle Zend_Log with the xml formatter its not works and give error


Posted by Benoît Durand (intiilapa) on 2011-03-13T14:36:18.000+0000

@Fabio, Can you provide a code to reproduce your problem?

Posted by Fabio Ginzel (fabioginzel) on 2011-03-15T19:45:28.000+0000


<pre class="highlight"> = Stream = APPLICATION_PATH "/../data/log/errors.log" = Xml

<pre class="highlight">
    protected function _initLogger() {
    $log = $this->getResource('log');
    if ($aa)
        echo "x";


Posted by Fabio Ginzel (fabioginzel) on 2011-03-15T19:46:00.000+0000


Fatal error: Uncaught exception 'DOMException' with message 'DOMElement::__construct() expects parameter 2 to be string, array given' in D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log\Formatter\Xml.php:152 Stack trace: #0 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log\Formatter\Xml.php(152): DOMElement->__construct('context', Array) #1 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log\Writer\Stream.php(131): Zend_Log_Formatter_Xml->format(Array) #2 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log\Writer\Abstract.php(85): Zend_Log_Writer_Stream->_write(Array) #3 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log.php(428): Zend_Log_Writer_Abstract->write(Array) #4 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log.php(594): Zend_Log->log('Undefined varia...', 5, Array) #5 D:\Sistemas\sas\sne_inscreve_evento\application\Bootstrap.php(10): Zend_Log->errorHandler(8, 'Undefined varia...', 'D:\Sistemas\sas...', 10, Array) #6 D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Application\Bootstrap\BootstrapAb in D:\Sistemas\sas\sne_inscreve_evento\library\Zend\Log\Formatter\Xml.php on line 152

Posted by Adam Lundrigan (adamlundrigan) on 2011-04-30T16:12:18.000+0000

@Fabio I have been able to reproduce your issue. I created a stock Zend Framework project using Zend_Tool:

<pre class="highlight">
zf create project test
cd test
zf create controller Test
mkdir -p data/logs
touch data/logs/application.log
chmod 777 data/logs/application.log

Then applied the following changes to add logging to the application (following instructions here:…):

<pre class="highlight">
diff --git a/application/Bootstrap.php b/application/Bootstrap.php
index 26169dd..6ea96e7 100644
--- a/application/Bootstrap.php
+++ b/application/Bootstrap.php
@@ -3,5 +3,11 @@
 class Bootstrap extends Zend_Application_Bootstrap_Bootstrap

+    protected function _initLogger()
+    {
+        $this->bootstrap('log');
+        $this->getResource('log')->registerErrorHandler();
+    }

diff --git a/application/configs/application.ini b/application/configs/application.ini
index d388364..8274c51 100644
--- a/application/configs/application.ini
+++ b/application/configs/application.ini
@@ -8,6 +8,11 @@ appnamespace = "Application"
 resources.frontController.controllerDirectory = APPLICATION_PATH "/controllers"
 resources.frontController.params.displayExceptions = 0 = "Stream" = APPLICATION_PATH "/../data/logs/application.log" = "a" = "Xml"
 [staging : production]

 [testing : production]
diff --git a/application/controllers/TestController.php b/application/controllers/TestController.php
index c4758fb..2d75c8d 100644
--- a/application/controllers/TestController.php
+++ b/application/controllers/TestController.php
@@ -11,6 +11,8 @@ class TestController extends Zend_Controller_Action
     public function indexAction()
         // action body
+        if ( $nonExistentVariable )
+            echo "Oh dear!";

When I open up my web browser and go to /test I see the output of the error handler controller and the following entry in data/logs/application.log:

<pre class="highlight">
2011-04-30T13:35:17-02:30Application error2CRITexception 'DOMException' with message 'DOMElement::__construct() expects parameter 2 to be string, array given' in /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log/Formatter/Xml.php:153
Stack trace:
#0 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log/Formatter/Xml.php(153): DOMElement->__construct('context', Array)
#1 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log/Writer/Stream.php(131): Zend_Log_Formatter_Xml->format(Array)
#2 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log/Writer/Abstract.php(85): Zend_Log_Writer_Stream->_write(Array)
#3 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log.php(428): Zend_Log_Writer_Abstract->write(Array)
#4 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Log.php(594): Zend_Log->log('Undefined varia...', 5, Array)
#5 /usr/local/apache2/htdocs/test/zf/test/application/controllers/TestController.php(15): Zend_Log->errorHandler(8, 'Undefined varia...', '/usr/local/apac...', 15, Array)
#6 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Controller/Action.php(513): TestController->indexAction()
#7 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Controller/Dispatcher/Standard.php(295): Zend_Controller_Action->dispatch('indexAction')
#8 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Controller/Front.php(954): Zend_Controller_Dispatcher_Standard->dispatch(Object(Zend_Controller_Request_Http), Object(Zend_Controller_Response_Http))
#9 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Application/Bootstrap/Bootstrap.php(97): Zend_Controller_Front->dispatch()
#10 /usr/local/apache2/htdocs/lib/ZendFramework-dev/library/Zend/Application.php(366): Zend_Application_Bootstrap_Bootstrap->run()
#11 /usr/local/apache2/htdocs/test/zf/test/public/index.php(26): Zend_Application->run()
#12 {main}2011-04-30T13:35:17-02:30Request Parameters2CRITtestindexdefault

Then I patched Zend_Log_Formatter_Xml to cast the argument to DOMElement to string, like so:

<pre class="highlight">
Index: library/Zend/Log/Formatter/Xml.php
--- library/Zend/Log/Formatter/Xml.php  (revision 23904)
+++ library/Zend/Log/Formatter/Xml.php  (working copy)
@@ -149,7 +149,7 @@
             if($key == "message") {
                 $value = htmlspecialchars($value, ENT_COMPAT, $enc);
-            $elt->appendChild(new DOMElement($key, $value));
+            $elt->appendChild(new DOMElement($key, (string)$value));

         $xml = $dom->saveXML();

And everything now works as expected: When visiting /test in a web browser you see the proper view script, and the application.log file contains:

<pre class="highlight">
2011-04-30T13:38:40-02:30Undefined variable: nonExistentVariable5NOTICE8/usr/local/apache2/htdocs/test/zf/test/application/controllers/TestController.php15Array

All tests in Zend_Log test suite still pass after applying my fix.

Posted by Adam Lundrigan (adamlundrigan) on 2011-04-30T16:22:43.000+0000

Fixed in trunk r23905

Posted by Satoru Yoshida (satoruyoshida) on 2011-05-03T10:27:11.000+0000

Hello, Adam. I will push [solve] button as proxy for You. If You want to release at next mini, You can merge this commit fron trunk to 1.11 branch.


Posted by Satoru Yoshida (satoruyoshida) on 2011-05-03T15:01:31.000+0000

Fixed 1.11 branch at 23957

Posted by Ralph Schindler (ralph) on 2011-05-03T19:02:06.000+0000

Reopened. Backed out r23905 from trunk in r23980 Backed out r23957 from release branch 1.11 in r23981

Posted by Benoît Durand (intiilapa) on 2011-05-04T17:31:37.000+0000

<pre class="highlight">

I have a problem with the commit r23905. Yes, it solves the fatal error, but the behavior is wrong. A context with the error handler is always an array. I think the formatters, and writers can't support array for context. It's related to the problem of array in ZF-10427 for extra info when you use the simple formatter.

I recommand to delete the optional parameter errcontext of the method Zend_Log::errorHandler().

<pre class="highlight">
PHP Notice:  Undefined variable: foo in /tmp/test.php on line 28

<pre class="highlight">
2011-05-04T19:17:55+02:00Undefined variable: foo5NOTICE8/tmp/test.php28

Why do you need more info than standard display with the context? Just to remind you, the context contains every variable in the scope.

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-04T17:52:57.000+0000


Thanks for summarizing our IRC chat from yesterday....I hadn't had a chance to do that yet :P

I completely agree. my patch was intended to prevent Zend_Log_Formatter_Xml::log from throwing a fatal error when non-string data was passed along to DOMElement. What you've described above better treats the source of the problem rather than just the symptom. Based on that, this is what I suggest"

<pre class="highlight">
Index: library/Zend/Log.php
--- library/Zend/Log.php        (revision 24002)
+++ library/Zend/Log.php        (working copy)
@@ -591,7 +591,7 @@
             } else {
                 $priority = Zend_Log::INFO;
-            $this->log($errstr, $priority, array('errno'=>$errno, 'file'=>$errfile, 'line'=>$errline, 'context'=>$errcontext));
+            $this->log($errstr, $priority, array('errno'=>$errno, 'file'=>$errfile, 'line'=>$errline));

         if ($this->_origErrorHandler !== null) {

In my opinion, this adequately treats the source of the problem (context data passed to the formatters, which can't handle it) while maintaining backwards compatibility (not changing the errorHandler() method signature and still passing $errcontext along to the original error handler (see Zend/Log.php:598))

Do you think this is an adequate solution? Are there any existing formatters which might want access to 'context'?

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-04T22:49:10.000+0000

I've been thinking about this some more, and I think a better solution would be to modify the behavior of the existing formatters which are unable to handle the context attribute to ignore it: * Firebug: Already covered, as context isn't included in it's output * Simple: Already covered, as context isn't included in it's output * Xml: Requires simple modification to ignore context:

<pre class="highlight">
Index: library/Zend/Log/Formatter/Xml.php
--- library/Zend/Log/Formatter/Xml.php  (revision 24002)
+++ library/Zend/Log/Formatter/Xml.php  (working copy)
@@ -146,10 +146,11 @@
         $elt = $dom->appendChild(new DOMElement($this->_rootElement));

         foreach ($dataToInsert as $key => $value) {
+            if($key == 'context') continue;
             if($key == "message") {
                 $value = htmlspecialchars($value, ENT_COMPAT, $enc);
-            $elt->appendChild(new DOMElement($key, $value));
+            $elt->appendChild(new DOMElement($key, (string)$value));

I chose to still cast $value to string, as that's what DOMElement constructor expects.

This solution solves the issue at hand, as well as still allowing future (or user-created) formatters to use the context element if they see fit.


Posted by Benoît Durand (intiilapa) on 2011-05-06T18:04:18.000+0000

People can already use the key context with Zend_Log::setEventItem() method. So, potential bc imao.

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-24T00:35:20.000+0000

Good point. How about this as an alternate implementation?

<pre class="highlight">
Index: library/Zend/Log/Formatter/Xml.php
--- library/Zend/Log/Formatter/Xml.php  (revision 24045)
+++ library/Zend/Log/Formatter/Xml.php  (working copy)
@@ -146,10 +146,12 @@
         $elt = $dom->appendChild(new DOMElement($this->_rootElement));

         foreach ($dataToInsert as $key => $value) {
-            if($key == "message") {
-                $value = htmlspecialchars($value, ENT_COMPAT, $enc);
+            if(empty($value) || is_scalar($value)) {
+                if($key == "message") {
+                    $value = htmlspecialchars($value, ENT_COMPAT, $enc);
+                }
+                $elt->appendChild(new DOMElement($key, (string)$value));
-            $elt->appendChild(new DOMElement($key, $value));

         $xml = $dom->saveXML();

This excludes an non-empty, non-scalar value from being included in the formatted output.

Posted by Chl (chl) on 2011-05-26T19:14:02.000+0000


in my case, I quite needed some informations in the $value (which was a POST with a subform). Could we try this ?

<pre class="highlight">
Index: library/Zend/Log/Formatter/Xml.php
--- library/Zend/Log/Formatter/Xml.php  (revision 24046)
+++ library/Zend/Log/Formatter/Xml.php  (copie de travail)
@@ -146,6 +146,9 @@
         $elt = $dom->appendChild(new DOMElement($this->_rootElement));
         foreach ($dataToInsert as $key => $value) {
+            if ( ! is_scalar($value)) {
+                $value = serialize($value);
+            }
             if($key == "message") {
                 $value = htmlspecialchars($value, ENT_COMPAT, $enc);

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-28T17:03:46.000+0000


That would assume the user of the log - be it a person or a parsing program - understands PHP serialization and can deserialize the value. My perspective is that the built-in log formatters should be simple, with more complex formatting needs implemented by the application to fit it's own use case.

The purpose of this issue, and the suggested fix, are only aimed at solving the issue at hand: usage of the XML formatter causes an exception to be raised. Discussions regarding changes to what the formatter outputs should be undertaken in a dedicated issue, on IRC, or on the mailing list.

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-29T00:47:59.000+0000

Fixed in trunk r24079 I've committed the patch suggested on 24/May/11 (exclude non-empty, non-scalar values from being included in the formatted output) Hoping that 2nd time is the charm ;)

Posted by Benoît Durand (intiilapa) on 2011-05-29T14:36:04.000+0000

@Chl I agree with Adam. @Adam Why are you excluded the empty value? It sounds like a little BC.

Posted by Adam Lundrigan (adamlundrigan) on 2011-05-29T14:57:56.000+0000

@intiilapa. Sorry, my initial wording was clumsy. The patch permits only empty and scalar values to be passed on to DOMElement.

Posted by Adam Lundrigan (adamlundrigan) on 2011-06-07T23:12:16.000+0000

Merged to release-1.11 in r24128

Posted by Martin (z3ndm@rt!n) on 2011-07-11T21:04:12.000+0000

This fix breaks functionality as described in the manual. When passing an exception to the log, the message is ignored.

The reason for this is the check on line 149 of Zend_Log_Formatter_Xml which uses" rel="nofollow">is_scalar() to check if the message has to be added to the log. An Exception object is not a scalar and is therefore ignored.

Possible fix: replace:

<pre class="highlight">

Posted by Matthew Weier O'Phinney (matthew) on 2011-07-13T18:22:37.000+0000

Opening due to comment activity

Posted by Matthew Weier O'Phinney (matthew) on 2011-07-13T18:23:23.000+0000

Added test that uses serializable object in event, and "applied" patch from Martin for testing for objects with __toString prior to rendering.

Have you found an issue?

See the Overview section for more details.


© 2006-2018 by Zend, a Rogue Wave Company. Made with by awesome contributors.

This website is built using zend-expressive and it runs on PHP 7.