Sonataadminbundle: HelperController setEnvironment throws deprectated ERROR 500

[develth]

Hey there,

i recognized that when i´m using sonata_type_collection on a OneToMany Entity, i get a silent status 500 from my apache / php 5.6 server.

I debugged until i got the error here:
https://github.com/sonata-project/SonataAdminBundle/blob/master/Controller/HelperController.php#L520

On symfony´s TwigRenderEngine it throws a deprecated that resolves into a Error 500.
https://github.com/symfony/symfony/blob/master/src/Symfony/Bridge/Twig/Form/TwigRendererEngine.php#L52
I´m using symfony 3.3.0

Any ideas on how to resolve it?

[develth]

By the way, this works perfectly on the same host - so i assume sonata admin is blocking anywhere?

https://gist.github.com/develth/0fd7940abbce2efdbc45202d3b9bd263

[greg0ire]

Wow that's really weird, a deprecation error should not resolve to a 500...

Also, the gist you are showing does something similar to line 52, not to line 37. And HelperController is calling setEnvironment, so not line 37.

i get a silent status 500

Do you mean a blank page? Anything interesting in your logs? If this is a blank page, does this means this happens in production only? And if yes, did you try to fix this in development?

[develth]

Line 520 in Helper Controller & Line 52 in TwigRenderer - sorry linked wrong thanks for notice - will edit it!

Yes - a total blank page. No Logs, no errors. totally silent.

If i do a die("error-debugging"); before line it stops. A die("error-debugging"); after line 52 is never reached.

[develth]

And i´m working on development environment! error_reporting is set to

error_reporting = E_ALL

[greg0ire]

By logs, I mean apache logs, not symfony logs BTW. Did you check both logs?

[develth]

Yip, both.
Apache Log (error log on LogLevel warn) is empty, symfony log:

[2017-06-05 15:52:31] request.INFO: Matched route "sonata_admin_append_form_element". {"route":"sonata_admin_append_form_element","route_parameters":{"_controller":"sonata.admin.controller.admin:appendFormFieldElementAction","_route":"sonata_admin_append_form_element"},"request_uri":"http://tool.tld/admin/core/append-form-field-element?code=admin.quiz&elementId=s59356201b3565_questions&uniqid=s59356201b3565","method":"POST"} []
[2017-06-05 15:52:31] security.DEBUG: Read existing security token from the session. {"key":"_security_main"} []
[2017-06-05 15:52:31] security.DEBUG: User was reloaded from a user provider. {"username":"tool-admin","provider":"Symfony\\Component\\Security\\Core\\User\\InMemoryUserProvider"} []
[2017-06-05 15:52:32] php.INFO: User Deprecated: The "Symfony\Bridge\Twig\Form\TwigRendererEngine::setEnvironment()" method is deprecated since version 3.3 and will be removed in 4.0. Pass the Twig Environment as second argument of the constructor instead. {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\ContextErrorException(code: 0): User Deprecated: The \"Symfony\\Bridge\\Twig\\Form\\TwigRendererEngine::setEnvironment()\" method is deprecated since version 3.3 and will be removed in 4.0. Pass the Twig Environment as second argument of the constructor instead. at /var/www/tool/htdocs/vendor/symfony/symfony/src/Symfony/Bridge/Twig/Form/TwigRendererEngine.php:50)"} []

[greg0ire]

It's as if your current error handler was treating this as a fatal error. You can find out what the current error handler is like this: https://stackoverflow.com/questions/12378644/how-can-i-retrieve-the-current-error-handler#25169684

And maybe you should do some step by step debugging there.

[greg0ire]

Also, is display_errors set to on?

[develth]

Just checking output of error_handler. is just a big never ending "waterfall"...
Display Error is on.

[greg0ire]

If I had to guess, I'd say your current error handler is this one. You could try to debug it. BTW, I was one of the last editors of this error handler, I hope this won't turn out to be my fault 😅

[develth]

$handlers = set_error_handler(function(){});
restore_error_handler();
foreach($handlers as $handler){
    $type= gettype($handler);
            if($type == "string"){
                var_dump( $handler);
            }else if($type == "object"){
                var_dump( get_class($handler));
            }
}
die();

This function outputs this before line 520:

string(36) "Symfony\Component\Debug\ErrorHandler" 
string(11) "handleError"

[greg0ire]

Hmm my bad, the error handler I modified is just used for phpunit it seems... You could debug Symfony\Component\Debug\ErrorHandler I guess

[develth]

Will do it later. Thanks for help until now!

At the moment i removed line 520 to make a little progress ;)

[greg0ire]

Might be unrelated, but some weird things are happening with Twig : https://github.com/twigphp/Twig/issues/2495

[greg0ire]

Could be a memory issue with sf also : https://github.com/symfony/symfony/pull/23007

[develth]

I can definitely exclude a memory issue. If I watch the memory on my unix machine, nothing "special" happens.

[greg0ire]

Okay well... weird. If I were you I'd still try to downgrade to sf 3.2, just in case.

[develth]

Thats my task before release if i couldn´t fix it until then. Because its so weird, i want to solve it ;)

[greg0ire]

If downgrading works, then maybe you can try to use git bisect to find the commit that breaks things

[develth]

Ok - strange. it seems to be the mentioned symfony/symfony#23007

If i replace the $errorAsException with e.g. "exception-check" from https://github.com/symfony/symfony/blob/master/src/Symfony/Component/Debug/ErrorHandler.php#L496 it works as expected.

But maybe it makes sense to remove the https://github.com/sonata-project/SonataAdminBundle/blob/master/Controller/HelperController.php#L520 in further versions for current sf versions.

[greg0ire]

But maybe it makes sense to remove the https://github.com/sonata-project/SonataAdminBundle/blob/master/Controller/HelperController.php#L520 in further versions for current sf versions.

It should be done conditionally. PRs are welcome :)

[greg0ire]

If i replace the $errorAsException with e.g. "exception-check" from https://github.com/symfony/symfony/blob/master/src/Symfony/Component/Debug/ErrorHandler.php#L496 it works as expected.

Can you please cherry-pick the whole commit https://github.com/symfony/symfony/pull/23007/commits/21ef0655942c0e75a3d58cc989f8ab26beb693e0 and post your findings?

You can get the patch here if it helps: https://github.com/symfony/symfony/commit/21ef0655942c0e75a3d58cc989f8ab26beb693e0.patch

[develth]

Sadly the same. Breaks at

$this->loggers[$type][0]->log($level, $logMessage, array('exception' => $errorAsException));

[greg0ire]

Can you wrap this in a try catch, and inside the catch, use var_dump($exception);die(); ? Make sure you catch \Throwable. We suspect this has to do with one of the monolog handlers you are using, or with the logger itself. What handlers are you using, BTW?

[develth]

The log handler was a good point. Thanks!

The issue was the predefined

    server_log:
        type:   server_log
        process_psr_3_messages: false
        host: 127.0.0.1:9911

in config_dev.yml

removed it and it works (but slow)!

[develth]

btw, a Throwable catch was never reached

[greg0ire]

Can you please continue the debugging here: https://github.com/symfony/symfony/blob/master/src/Symfony/Bridge/Monolog/Handler/ServerLogHandler.php#L44 ?

[develth]

For what should i check? I have nothing running with 127.0.0.1:9911

[greg0ire]

Ah this should explain a lot... but getting a blank page is not great. Oh and then : https://github.com/symfony/symfony/blob/master/src/Symfony/Bridge/Monolog/Handler/ServerLogHandler.php#L48 This is why you get a blank page.

[jordisala1991]

I think this is related to a twig bug we already fix. Closing for now. If this should remain opened please ping me