How Devel causes heisenbugs

Here’s what killed my Friday.
The story has been edited to remove pain, suffering, prolonged coffee intake.

Inside a module I have code similar to the commerce cart refresh code.
It loads a line item, clones it, runs pricing rules and other modifications on the created clone. Then it compares the cloned and original line items to determine whether something had changed (requiring the line item in the database to be updated).

That looks something like this:

$line_item = commerce_line_item_load($line_item_id);
// dsm($line_item)
$cloned_line_item = clone $line_item;
// Pretend that as a result of a complex calculation
// or function call, the unit price of the new line 
// item has been changed.
$cloned_line_item->commerce_unit_price[LANGUAGE_NONE][0] = array(
  'amount' => '66600', 
  'currency_code' => 'EUR',
);
// Now let's compare the old and the new amount.
$old_amount = $line_item->commerce_unit_price[LANGUAGE_NONE][0]['amount'];
$new_amount = $cloned_line_item->commerce_unit_price[LANGUAGE_NONE][0]['amount'];
if ($old_amount != $new_amount) {
  dsm('The price has been changed.');
  commerce_line_item_save($cloned_line_item);
}
else {
  dsm('This can never happen.');
}

I am using Devel to do some light debugging. At one point, wanting to see which
line items get processed, I uncomment the dsm($line_item) on top of the script.

Suddenly, the output changes to “This can never happen.”. What happened?
The dsm call had turned the line item variables (such as commerce_unit_price) into references. PHP’s clone is a shallow clone, so it only cloned the line item, not caring about what’s inside.
With both $line_item and $cloned_line_item having the same references for its fields, changing $cloned_line_item->commerce_unit_price also changed $line_item->commerce_unit_price. This means that the line item in the entity controller static cache has been changed as well, so doing another commerce_line_item_load() inside the same request will return a line item with the wrong unit price.
Many subtle bugs followed, followed with suspicious glances at Entity Wrapper (later proved to be innocent).

So, my simple debugging call caused all of the bugs I was seeing from that point on.

Futurama: You changed the outcome by measuring it

There’s an issue in Devel’s issue queue from November 2012 about this:
Krumo side effect: Object vars become references.
Click the “follow” button, and be very careful what you use Devel for.
Note that Devel in D8 uses Kint instead of Krumo, so it might be immune to this.

About these ads

3 thoughts on “How Devel causes heisenbugs

Comments are closed.