Magento – Mage::log writes to the screen

debugging

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.

Best Answer

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.

Related Topic