21

I have a development system, display_errors is on, Magento is in developer mode and I tried to

Mage::log($layered_navigation_filter_block); // Mage_Catalog_Block_Layer_Filter_Attribute

And everything was written to the screen instead of the log file, why?

It looks like this case:

// app/Mage.php:837
if (is_array($message) || is_object($message)) {
    $message = print_r($message, true);
}

but the second argument from the print_r is ignored:

Mage_Catalog_Block_Layer_Filter_Category Object ( [_filter:protected] => ...

 

[28-Jan-2013 22:48:43 UTC] PHP Fatal error:  Allowed memory size of 268435456 bytes exhausted (tried to allocate 241434624 bytes) in /var/www/app/code/local/MyCompany/Motif/Model/Observer.php on line 47
[28-Jan-2013 22:48:43 UTC] PHP Stack trace:
[28-Jan-2013 22:48:43 UTC] PHP   1. {main}() /var/www/index.php:0
[28-Jan-2013 22:48:43 UTC] PHP   2. Mage::run() /var/www/index.php:87
[28-Jan-2013 22:48:43 UTC] PHP   3. Mage_Core_Model_App->run() /var/www/app/Mage.php:683
[28-Jan-2013 22:48:43 UTC] PHP   4. Mage_Core_Controller_Varien_Front->dispatch() /var/www/app/code/core/Mage/Core/Model/App.php:354
[28-Jan-2013 22:48:43 UTC] PHP   5. Mage_Core_Controller_Varien_Router_Standard->match() /var/www/app/code/core/Mage/Core/Controller/Varien/Front.php:176
[28-Jan-2013 22:48:43 UTC] PHP   6. Mage_Core_Controller_Varien_Action->dispatch() /var/www/app/code/core/Mage/Core/Controller/Varien/Router/Standard.php:250
[28-Jan-2013 22:48:43 UTC] PHP   7. Mage_Catalog_CategoryController->viewAction() /var/www/app/code/core/Mage/Core/Controller/Varien/Action.php:419
[28-Jan-2013 22:48:43 UTC] PHP   8. Mage_Core_Controller_Varien_Action->generateLayoutBlocks() /var/www/app/code/core/Mage/Catalog/controllers/CategoryController.php:146
[28-Jan-2013 22:48:43 UTC] PHP   9. Mage_Core_Model_Layout->generateBlocks() /var/www/app/code/core/Mage/Core/Controller/Varien/Action.php:344
[28-Jan-2013 22:48:43 UTC] PHP  10. Mage_Core_Model_Layout->generateBlocks() /var/www/app/code/core/Mage/Core/Model/Layout.php:210
[28-Jan-2013 22:48:43 UTC] PHP  11. Mage_Core_Model_Layout->_generateBlock() /var/www/app/code/core/Mage/Core/Model/Layout.php:205
[28-Jan-2013 22:48:43 UTC] PHP  12. Mage_Core_Model_Layout->addBlock() /var/www/app/code/core/Mage/Core/Model/Layout.php:239
[28-Jan-2013 22:48:43 UTC] PHP  13. Mage_Core_Model_Layout->createBlock() /var/www/app/code/core/Mage/Core/Model/Layout.php:472
[28-Jan-2013 22:48:43 UTC] PHP  14. Mage_Core_Block_Abstract->setLayout() /var/www/app/code/core/Mage/Core/Model/Layout.php:456
[28-Jan-2013 22:48:43 UTC] PHP  15. Mage::dispatchEvent() /var/www/app/code/core/Mage/Core/Block/Abstract.php:239
[28-Jan-2013 22:48:43 UTC] PHP  16. Mage_Core_Model_App->dispatchEvent() /var/www/app/Mage.php:447
[28-Jan-2013 22:48:43 UTC] PHP  17. Mage_Core_Model_App->_callObserverMethod() /var/www/app/code/core/Mage/Core/Model/App.php:1317
[28-Jan-2013 22:48:43 UTC] PHP  18. MyCompany_Motif_Model_Observer->coreBlockAbstractPrepareLayoutAfter() /var/www/app/code/core/Mage/Core/Model/App.php:1338
[28-Jan-2013 22:48:43 UTC] PHP  19. print_r() /var/www/app/code/local/MyCompany/Motif/Model/Observer.php:47

Ok, a fatal error happens, no shutdown_function is registered, so why is the print_r echoed? :-) I still don't understand what is happening.

  • Is the output you're getting on the screen the block object dump or is it an exception? You could be catching an exception before Mage::log is getting called. – mybluevan Jan 28 '13 at 19:39
  • What, exactly, what written to the screen? – Alan Storm Jan 28 '13 at 19:52
  • updated the question – Fabian Blechschmidt Jan 28 '13 at 20:01
  • What Stack, Magento and/or PHP version are you using? – B00MER Jan 28 '13 at 20:52
  • MAMP PRO (Apache/2.2.22, PHP 5.4.3) magento 1.7.0.2 – Fabian Blechschmidt Jan 28 '13 at 20:56
29

I created a really short and sweet reproducible test case for this:

<?php

error_reporting(-1);
ini_set('display_errors', true);
ini_set('memory_limit', '1M');

$chunk = base64_encode(openssl_random_pseudo_bytes(1024));

while (true) {
    $a[] = print_r($chunk, true);
}

The reason you are seeing the information put out is due to print_r using output buffering internally to capture it's information. Take a look at the definition of the print_r function from the PHP source:

/* {{{ proto mixed print_r(mixed var [, bool return])
   Prints out or returns information about the specified variable */
PHP_FUNCTION(print_r)
{
    zval *var;
    zend_bool do_return = 0;

    if (zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, "z|b", &var, &do_return) == FAILURE) {
        RETURN_FALSE;
    }

    if (do_return) {
        php_start_ob_buffer (NULL, 0, 1 TSRMLS_CC);
    }

    zend_print_zval_r(var, 0 TSRMLS_CC);

    if (do_return) {
        php_ob_get_buffer (return_value TSRMLS_CC);
        php_end_ob_buffer (0, 0 TSRMLS_CC);
    } else {
        RETURN_TRUE;
    }
}

Because PHP is running out of memory and dying, the output buffer is being flushed before print_r clears it out via it's call to php_ob_get_buffer

I'm not sure there is going to be anyway around this. Just make sure you disable that logging in production, or run mod_security to prevent this type of output from going to the page.

  • Thank you very much for this detailed answer. I should restart learning C and read php sourcecode :) – Fabian Blechschmidt Jan 29 '13 at 20:45
6

What davidalger points out is important. The object you're trying to log is too big and is causing PHP to run out of memory. Depending on your memory limit and the size of your block you might be able to use:

Mage::log($layered_navigation_filter_block->debug());

All objects that extend Varien_Object can use debug() to output the underlying _data property recursively.

Check out this blog post by one of my co-workers for a more detailed explanation.

2

could this be the reason?

https://stackoverflow.com/questions/9329877/using-print-r-in-ob-start

"From the PHP documentation: When the return parameter is used, this function uses internal output buffering so it can not be used inside an ob_start() callback function." More info here: [php.net/manual/en/function.print-r.php]

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.