Logger exception handler generates a badly formatted log message #2555

Closed
zfbot opened this Issue Sep 28, 2012 · 9 comments

Comments

Projects
None yet
5 participants
@zfbot

zfbot commented Sep 28, 2012

Jira Information

Original Issue:ZF2-520
Issue Type:Bug
Reporter:yonman
Created:09/04/12
Assignee:weierophinney
Components:Zend\Log

Description

ZF2 RC7
Steps to reproduce:
Initialize logging with writer and register the exception handler Logger::registerExceptionHandler
Create a view script that throws an exception
Dispatch the controller
Note that request fails

Expected
Log will hold a properly formatted exception message with readable trace, e.g.

ERR (3): exception 'Zend\Form\Exception\DomainException' with message 'Zend\Form\View\Helper\FormLabel::__invoke expects either label ..... Form/View/Helper/FormLabel.php:114
Stack trace:
#0 [internal function]: Zend\Form\View\Helper\FormLabel->__invoke(Object(Zend\Form\Element))
#1 /home/yonni/Zend/workspaces/DefaultWorkspace/ZendFramework-minimal-2.0.0rc7/library/Zend/View/Renderer/PhpRenderer.php(353): call_user_func_array(Object(Zend\Form\View\Helper\FormLabel), Array)
#2 /home/yonni/Zend/workspaces/DefaultWorkspace/gui.new/module/ZendServer/src/ZendServer/View/Helper/Form/Renderer/Table.php(36): Zend\View\Renderer\PhpRenderer->__call('FormLabel', Array)

Actual
Log holds a json_encoded trace which is very difficult to decipher and seems to have gone through multiple character escaping. The entry is one long string, I broke it apart for easier reading

Zend\Form\View\Helper\FormLabel::__invoke expects ..... neither found {"file":"\/home\/yonni\/Zend\/workspaces\/DefaultWorkspace\/ZendFramework-minimal-2.0.0rc7\/library\/Zend\/Form\/View\/Helper\/FormLabel.php","line":114,"trace":"[\"
{\\\"function\\\":\\\"__invoke\\\",\\\"class\\\":\\\"Zend\\\\\\\\Form\\\\\\\\View\\\\\\\\Helper\\\\\\\\FormLabel\\\",\\\"type\\\":\\\"->\\\",\\\"args\\\":\\\"
[\\\\\\\"object(Zend\\\\\\\\\\\\\\\\Form\\\\\\\\\\\\\\\\Element) {}\\\\\\\"]\\\"}\",
\"{\\\"file\\\":\\\"\\\\\\\/home\\\\\\\/yonni\\\\\\\/Zend\\\\\\\/workspaces\\\\\\\/DefaultWorkspace\\\\\\\/ZendFramework-minimal-2.0.0rc7\\\\\\\/library\\\\\\\/Zend\\\\\\\/View\\\\\\\/Renderer\\\\\\\/PhpRenderer.php\\\",\\\"line\\\":353,\\\"function\\\":\\\"call_user_func_array\\\",\\\"args\\\":
\\\"[\\\\\\\"object(Zend\\\\\\\\\\\\\\\\Form\\\\\\\\\\\\\\\\View\\\\\\\\\\\\\\\\Helper\\\\\\\\\\\\\\\\FormLabel) {}\\\\\\\",
\\\\\\\"[\\\\\\\\\\\\\\\"object(Zend\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\Form\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\Element) {}\\\\\\\\\\\\\\\"]\\\\\\\"]\\\"}\",
\"{\\\"file\\\":\\\"\\\\\\\/home\\\\\\\/yonni\\\\\\\/Zend\\\\\\\/workspaces\\\\\\\/DefaultWorkspace\\\\\\\/gui.new\\\\\\\/module\\\\\\\/ZendServer\\\\\\\/src\\\\\\\/ZendServer\\\\\\\/View\\\\\\\/Helper\\\\\\\/Form\\\\\\\/Renderer\\\\\\\/Table.php\\\",\\\"line\\\":36,\\\"function\\\":\\\"__call\\\",\\\"class\\\":\\\"Zend\\\\\\\\View\\\\\\\\Renderer\\\\\\\\PhpRenderer\\\",\\\"type\\\":\\\"->\\\",\\\"args\\\":\\\"[\\\\\\\"FormLabel\\\\\\\",\\\\\\\"[\\\\\\\\\\\\\\\"object(Zend\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\Form\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\Element) {}\\\\\\\\\\\\\\\"]\\\\\\\"]\\\"}\",\"{\\\"file\\\":\\\"\\\\\\\/home\\\\\\\/yonni
.....

To resolve this locally I changed the following line (Zend\Log\Logger.php:437)

$logger->log(Logger::ERR, $exception->getMessage(), $extra);

To

$logger->log(Logger::ERR, $exception);

Effectively forcing the logger to use its own internal normalization and formatter

@zfbot

This comment has been minimized.

Show comment
Hide comment
@zfbot

zfbot Sep 28, 2012

(Originally posted by: b-durand on 09/11/12)

You can define your own exception handler. I don't think that we use the toString render of an exception, but improve the exception formatter.

I hope that you have extended your zf2 version instead of change the file. Do you know it's bad (practice)?

Too many slashes :)

zfbot commented Sep 28, 2012

(Originally posted by: b-durand on 09/11/12)

You can define your own exception handler. I don't think that we use the toString render of an exception, but improve the exception formatter.

I hope that you have extended your zf2 version instead of change the file. Do you know it's bad (practice)?

Too many slashes :)

@zfbot

This comment has been minimized.

Show comment
Hide comment
@zfbot

zfbot Sep 28, 2012

(Originally posted by: yonman on 09/12/12)

Naturally, extended outside the framework.
Just to be sure this is clear - the same thing happens when any sort of extras array is passed, not only exceptions

zfbot commented Sep 28, 2012

(Originally posted by: yonman on 09/12/12)

Naturally, extended outside the framework.
Just to be sure this is clear - the same thing happens when any sort of extras array is passed, not only exceptions

@zfbot

This comment has been minimized.

Show comment
Hide comment
@zfbot

zfbot Sep 28, 2012

This issue was ported from the ZF2 Jira Issue Tracker at
http://framework.zend.com/issues/browse/ZF2-520

Known GitHub users mentioned in the original message or comment:
@YonmaN, @weierophinney, @b-durand

zfbot commented Sep 28, 2012

This issue was ported from the ZF2 Jira Issue Tracker at
http://framework.zend.com/issues/browse/ZF2-520

Known GitHub users mentioned in the original message or comment:
@YonmaN, @weierophinney, @b-durand

@ralphschindler

This comment has been minimized.

Show comment
Hide comment
@ralphschindler

ralphschindler Feb 8, 2013

Member

Is this still an issue?

Member

ralphschindler commented Feb 8, 2013

Is this still an issue?

@YonmaN

This comment has been minimized.

Show comment
Hide comment
@YonmaN

YonmaN Feb 14, 2013

This is still an issue - using the error handler as-is produces an unreadable and unusable json string. Correcting this issue from outside the framework is difficult and eventually requires you to override most of the functionality provided out of the box.

YonmaN commented Feb 14, 2013

This is still an issue - using the error handler as-is produces an unreadable and unusable json string. Correcting this issue from outside the framework is difficult and eventually requires you to override most of the functionality provided out of the box.

@ralphschindler

This comment has been minimized.

Show comment
Hide comment
@ralphschindler

ralphschindler Feb 14, 2013

Member

@weierophinney you just worked on Json stuffs, what are your thoughts here?

Member

ralphschindler commented Feb 14, 2013

@weierophinney you just worked on Json stuffs, what are your thoughts here?

@YonmaN

This comment has been minimized.

Show comment
Hide comment
@YonmaN

YonmaN May 2, 2013

So, while this isn't a fun problem it still is an issue for logging as the output is not valid json nor is it easily human readable. Any news on this?

YonmaN commented May 2, 2013

So, while this isn't a fun problem it still is an issue for logging as the output is not valid json nor is it easily human readable. Any news on this?

@gws

This comment has been minimized.

Show comment
Hide comment
@gws

gws Jun 13, 2013

Contributor

@YonmaN There were a number of fixes recently to Zend\Log including zendframework#4616 - can you try this again on recent master?

Contributor

gws commented Jun 13, 2013

@YonmaN There were a number of fixes recently to Zend\Log including zendframework#4616 - can you try this again on recent master?

@gws

This comment has been minimized.

Show comment
Hide comment
@gws

gws Aug 27, 2013

Contributor

@ralphschindler @weierophinney I believe this has been fixed and should be closed. I confirmed that the following script (running from the CLI in the ZendSkeletonApplication root under ZF 2.2.4:

<?php                                                                                                    

require_once 'init_autoloader.php';

use Zend\Log;

$logger = new Log\Logger;
$writer = new Log\Writer\Stream('php://output');
$logger->addWriter($writer);

Log\Logger::registerExceptionHandler($logger);

throw new Exception('test');

produces nicely formatted JSON:

2013-08-27T04:33:43+00:00 ERR (3): test {"file":"/path/to/my/file.php","line":13,"trace":"[]","xdebug":"\nException: test in /path/to/my/file.php on line 13\n\nCall Stack:\n    0.0002     225160   1. {main}() /path/to/my/file.php:0\n"}
Contributor

gws commented Aug 27, 2013

@ralphschindler @weierophinney I believe this has been fixed and should be closed. I confirmed that the following script (running from the CLI in the ZendSkeletonApplication root under ZF 2.2.4:

<?php                                                                                                    

require_once 'init_autoloader.php';

use Zend\Log;

$logger = new Log\Logger;
$writer = new Log\Writer\Stream('php://output');
$logger->addWriter($writer);

Log\Logger::registerExceptionHandler($logger);

throw new Exception('test');

produces nicely formatted JSON:

2013-08-27T04:33:43+00:00 ERR (3): test {"file":"/path/to/my/file.php","line":13,"trace":"[]","xdebug":"\nException: test in /path/to/my/file.php on line 13\n\nCall Stack:\n    0.0002     225160   1. {main}() /path/to/my/file.php:0\n"}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment