Magento: Debugging with Varien Object

When you start digging through Magento’s internals to debug some problem, you often reach a point where you say to yourself

OK, my system’s misbehaving because this object has this value set for a property

The problem then becomes

What set that value!?

Discovering where this is can be trickier than it seems. While PHP step debuggers exist, they aren’t as common as they should be in most PHP development stacks. Additionally, Magento’s abstractions often mean an object hops around all over the place, and revisits the same places over and over again. This quickly gets dizzying. Finally, there’s the common problem of debugging where, having written buggy code, you probably have a natural blind stop as to why the code’s buggy (or else your solution wouldn’t have the bug).

This article is going to dive into Magento’s object implementation, and along the way we’ll solve the problem laid out above.

Everything’s a Varien_Object

In Magento, most of the objects that you set data on (Models, Blocks), ultimately inherit from the class Varien_Object.

#File: lib/Object/Varien.php
/**
 * Varien Object
 *
 * @category   Varien
 * @package    Varien_Object
 * @author      Magento Core Team <core@magentocommerce.com>
 */
class Varien_Object implements ArrayAccess
{
    ...
}    

This is a common pattern in Object Oriented Programming. By having all your objects of a particular type share a common ancestor, you can write methods that are shared across your entire code base.

One of the things Varien_Object provides is Magento’s famous “getter” and “setter” methods.

$address = $customer->getAddress();
$customer->setFirstName('John');

These methods are implemented via PHP’s magic __call method. Since the customer object referenced above doesn’t have a setFirstName function, PHP calls Varien_Object‘s __call method (shown partially below)

public function __call($method, $args)
{
    switch (substr($method, 0, 3)) {
        case 'get' :
            //Varien_Profiler::start('GETTER: '.get_class($this).'::'.$method);
            $key = $this->_underscore(substr($method,3));
            $data = $this->getData($key, isset($args[0]) ? $args[0] : null);
            //Varien_Profiler::stop('GETTER: '.get_class($this).'::'.$method);
            return $data;
    ...

The __call method looks for method names that start with get or set, and if found uses the rest of the name to operate on a data store. This means that all calls to the magic getters and setters are actually wrappers for the getData and setData methods on the object. In turn, that means we can use this to listen into any data property being set on a Magento Model!

Wiretapping Varien_Object

So, let’s get going. The first thing we’ll want to do is create a local override of Varien_Object. While we wouldn’t want to build-out a feature like this (or, depending on our schedule, we might), as a debugging exercise it more than passes the smell test. First, create the folder structure for our override

mkdir app/code/local/Varien/

next, copy the Varien_Object in lib to its new folder.

cp -n lib/Varien/Object.php app/code/local/Varien/Object.php

Finally, edit the new Object.php so its setData method includes a line for logging

public function setData($key, $value=null)
{
    Mage::Log("Setting the key " . $key . " on a " . get_class($this) );

Reload any page on your system, and your log should now be filled with over a thousand lines reporting every single time an object’s data property was set. You can quickly isolate a particular class, object, and key with some conditional logic. Try something like this

public function setData($key, $value=null)
{

    if($key == 'created_at' && get_class($this) == 'Mage_Catalog_Model_Product')
    {
        Mage::Log("Setting the key " . $key . " on a " . get_class($this) );
        Mage::Log("The product ID is " . $this->getId());
        Mage::Log($this->getData());
    }

With that in place, reload the product detail page, and you’ll see something like

2011-02-26T05:03:00+00:00 DEBUG (7): Setting the key created_at on a Mage_Catalog_Model_Product
2011-02-26T05:03:00+00:00 DEBUG (7): The product ID is 133
2011-02-26T05:03:00+00:00 DEBUG (7): Array
(
    [store_id] => 1
    [entity_id] => 133
    [entity_type_id] => 10
    [attribute_set_id] => 9
    [type_id] => simple
    [sku] => ac9003
)

in the log file.

Getting a Call Stack

So, by leveraging that damned Object Oriented Programming, we’ve been able to tap into the point where a certain property is being set. However, we still don’t know exactly where in the code base this is happening. That’s where the PHP functions debug_backtrace and debug_print_backtrace come into the picture.

These functions return a PHP call stack. A call stack contains a list of every function that’s been called so far in a program

called_third(...);
called_second(...);
called_first(...);
main(...);

Using these functions, we can tell exactly which methods called setData. The debug_print_backtrace function will print this information out to the browser/console, whereas debug_backtrace will return a structured array with the same data. Be careful, as these functions will report on parameters as well, and outputting very-large-objects-with-circular-references may cause PHP to exhaust its memory limit.

Relying on this sort of reflection for core program functionality is always a little dicey, but when you’re diagnosing problems it can be a life saver. Let’s give the following a try

public function setData($key, $value=null)
{

    if($key == 'created_at' && get_class($this) == 'Mage_Catalog_Model_Product')
    {
        foreach(debug_backtrace() as $key=>$info)
        {
            Mage::Log("#" . $key . 
            " Called " . 
            $info['function'] .
            " in " .
            $info['file'] .
            " on line " .
            $info['line']);            
        }
    }

Reload your page, and something like this will be written out to the logs

2011-02-26T05:16:41+00:00 DEBUG (7): #0 Called setData in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Catalog/Model/Abstract.php on line 180
2011-02-26T05:16:41+00:00 DEBUG (7): #1 Called setData in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/local/Varien/Object.php on line 192
2011-02-26T05:16:41+00:00 DEBUG (7): #2 Called addData in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Eav/Model/Entity/Abstract.php on line 870
2011-02-26T05:16:41+00:00 DEBUG (7): #3 Called load in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Catalog/Model/Resource/Eav/Mysql4/Abstract.php on line 647
2011-02-26T05:16:41+00:00 DEBUG (7): #4 Called load in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Core/Model/Abstract.php on line 225
2011-02-26T05:16:41+00:00 DEBUG (7): #5 Called load in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Catalog/controllers/ProductController.php on line 60
2011-02-26T05:16:41+00:00 DEBUG (7): #6 Called _initProduct in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Catalog/controllers/ProductController.php on line 194
2011-02-26T05:16:41+00:00 DEBUG (7): #7 Called viewAction in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Core/Controller/Varien/Action.php on line 425
2011-02-26T05:16:41+00:00 DEBUG (7): #8 Called dispatch in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Core/Controller/Varien/Router/Standard.php on line 255
2011-02-26T05:16:41+00:00 DEBUG (7): #9 Called match in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Core/Controller/Varien/Front.php on line 176
2011-02-26T05:16:41+00:00 DEBUG (7): #10 Called dispatch in /Users/alanstorm/Sites/magento1point4.2.dev/app/code/core/Mage/Core/Model/App.php on line 304
2011-02-26T05:16:41+00:00 DEBUG (7): #11 Called run in /Users/alanstorm/Sites/magento1point4.2.dev/app/Mage.php on line 596
2011-02-26T05:16:41+00:00 DEBUG (7): #12 Called run in /Users/alanstorm/Sites/magento1point4.2.dev/index.php on line 80

As you can see, we now have an exact map of each method that was called (along with a file and line number) leading up to this point in the code. That should be more than enough information to continue debugging our problem.

Now that we’re done with our wiretapping, we should clean-up our Object.php override.

mv app/code/local/Varien/Object.php /tmp/Object.php 

This sort of logging is fine for short term use, but it’s not something we’d want lingering around a production system.

Wrap Up

With the tools provided in this article, you no longer need to pull out your hair in frustration when tracking a particular data property through Magento’s complex object hierarchy. You’ve also seen one of the key benefits of modern software development. Language wars are a dime a dozen, but if one clear trend have developed in the past 30 years, it’s that languages and systems with this sort of reflection, and the ability to observe, and even change, their own behavior are the ones that win.