ZF-11161: RegisterErrorHandle not work with Xml formatter

Description

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

Comments

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

Application.ini:


resources.log.stream.writerName = Stream
resources.log.stream.writerParams.stream = APPLICATION_PATH "/../data/log/errors.log"
resources.log.stream.formatterName = Xml

    protected function _initLogger() {
    $this->bootstrap('log');
    $log = $this->getResource('log');
    $log->registerErrorHandler();
    if ($aa)
        echo "x";

    }

error:

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

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


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: http://framework.zend.com/manual/en/…):


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

+resources.log.stream.writerName = "Stream"
+resources.log.stream.writerParams.stream = APPLICATION_PATH "/../data/logs/application.log"
+resources.log.stream.writerParams.mode = "a"
+resources.log.stream.formatterName = "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:


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:


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:


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.

Fixed in trunk r23905

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.

Thanks.

Fixed 1.11 branch at 23957

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


Array

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().


PHP Notice:  Undefined variable: foo in /tmp/test.php on line 28

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.

Benoît,

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"


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'?

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:


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.

Comments?

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

Good point. How about this as an alternate implementation?


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.

Hello,

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


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);
             }

@Chl:

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.

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 ;)

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

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

Merged to release-1.11 in r24128

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 www.php.net/is_scalar" 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:


with:

Opening due to comment activity

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