hook_commerce_payment_order_paid_in_full() does not fire in module hook

Actually, we are invoking this event with rules_invoke_all('commerce_payment_order_paid_in_full', ...), so the corresponding hook should be getting invoked. After adding your hook implementation did you clear your cache? Drupal 7 keeps a registry of hook implementations, so you have to clear the cache after adding an implementation to a module to ensure it gets rebuilt.

Curious... to debug you might add drupal_set_message('<pre>'. print_r($balance, TRUE) .'</pre>'); to line 355 of commerce_payment.module. Perhaps there's some floating point math error preventing it from recognizing the order is paid in full.

Same issue. Gonna do some debugging.

I can't find anywhere commerce_order_commerce_payment_transaction_update() is called. Which in turn calls commerce_order_commerce_payment_transaction_insert(), which in turn calls hook_commerce_payment_order_paid_in_full().

At least in the Drupal Commerce code base. Nor in commerce_paypal or commerce_authnet.

Are these contrib modules too old and need to be updated to use these new hooks or something?

commerce_checkout_form_submit() does all sorts of things with clearing + restoring messages (aka dpm(), drupal_set_message()) may not be displaying as expected and should not be relied on. watchdog may be the best place to do debugging here.

Balance for what ever reason is not 0. it's set to the full amount.

Here's my debug from watchdog.

balance:
Array
(
    [amount] => 49000
    [currency_code] => USD
)

Ok, I've taken this as far as I can go.

The problem is in the workflow,

function commerce_payment_order_balance($order, $totals = array()) is not able to get at the most recent transaction. I believe this is because the revision is not yet in the database.

On the other hand, the primary entry is in database (commerce_payment_transaction), just not the revision table (commerce_payment_transaction_revision) for what ever reason.

This is returning 0 results.
$transactions = commerce_payment_transaction_load_multiple(array(), array('order_id' => $order->order_id));

Even is you pass $reset = TRUE into load_multiple.

I know the original entry is in the database because I've added this debugging statement:

function commerce_payment_transaction_load_multiple($transaction_ids = array(), $conditions = array(), $reset = FALSE) {
  watchdog('debug', 'TRANACTION_IDS = <pre>' . print_r($transaction_ids, TRUE) . "</pre>Conditions = <pre>" . print_r($conditions, TRUE) . '</pre>RESET = ' . ($reset ? 1 : 0));
  $record = db_select("commerce_payment_transaction", "t")
    ->fields("t")
    ->condition('order_id', $conditions['order_id'])
    ->execute()
    ->fetchAssoc();
  watchdog('debug', 'RECORD = <pre>' . print_r($record, TRUE) . '</pre>');
  $result = entity_load('commerce_payment_transaction', $transaction_ids, $conditions, TRUE);
  watchdog('debug', 'result: <pre>' . print_r($result, TRUE) . '</pre>');
  return $result;
}

I've added this to debug in includes/entity.inc around line 196

...
if ($ids === FALSE || $ids || $revision_id || ($conditions && !$passed_ids)) {
  $query = $this->buildQuery($ids, $conditions, $revision_id);
  // Debug added
  if(isset($conditions['order_id'])) {
    watchdog('debug', 'buildquery: <pre>' . dpq($query, TRUE) . '</pre>');
    $result = db_query(dpq($query, TRUE));
    watchdog('debug', 'build query result <pre>' . print_r($result->fetchAll(), TRUE) . '</pre>');
  }
  $queried_entities = $query
    ->execute()
    ->fetchAllAssoc($this->idKey);
}

To confirm the transaction is entered correctly after it's all said and done, I've copied the query outputted from includes/entity.inc and put it in here

function commerce_payment_transaction_save($transaction) {
  watchdog('debug', 'commerce_payment_transaction_save');
  $result = entity_get_controller('commerce_payment_transaction')->save($transaction);
  // This query is taken from a dpq() i've added into `public function load($ids = array(), $conditions = array())` in includes/entity.inc
  $result2 = db_query("SELECT revision.revision_id AS revision_id, revision.revision_uid AS revision_uid, revision.remote_id AS remote_id, revision.message AS message, revision.message_variables AS message_variables, revision.amount AS amount, revision.currency_code AS currency_code, revision.status AS status, revision.remote_status AS remote_status, revision.log AS log, revision.revision_timestamp AS revision_timestamp, revision.data AS data, base.transaction_id AS transaction_id, base.uid AS uid, base.order_id AS order_id, base.payment_method AS payment_method, base.instance_id AS instance_id, base.payload AS payload, base.created AS created, base.changed AS changed FROM {commerce_payment_transaction} base INNER JOIN {commerce_payment_transaction_revision} revision ON revision.revision_id = base.revision_id WHERE  (base.order_id = '".$transaction->order_id."')");
  return $result;
}

Here's the workflow from my logs:

• commerce_authnet_aim_submit_form_submit();
• START commerce_payment_transaction_save();
• commerce_order_commerce_payment_transaction_update();
• commerce_order_commerce_payment_transaction_insert();
• END commerce_payment_transaction_save();

This means that commerce_order_commerce_payment_transaction_update() & commerce_order_commerce_payment_transaction_insert() are called before commerce_payment_transaction_save() exits.

I believe after commerce_payment_transaction_save() exists, the revision is entered, but not before. Here lies the issue.

I have no idea how to fix.

There's also a bug in this work flow which eats all the DPM()'s . I believe this bug should also be resolved, as it hurts the ease of debugging this critical part of the code.

Subscribe

Since many people will require this functionality for triggering functionality once sales are finished, I consider it a release blocker, so I'm moving this to critical.

I can confirm this bug on a default install of commerce kickstart when testing a transaction with commerce_authnet.

Thanks for the research.

We need a more complete description of the bug. Can you please give a complete synopsis?

From http://drupal.org/node/73179:

Description: The Description field is wide open which leaves you a lot of space to say a lot or a little. The Description takes the title one step further. Generally speaking, the majority of the time spent fixing an issue is spent on understanding the problem and finding the cause of that issue. The goal of the description is to state the exact set of conditions that cause a problem and the resultant undesirable state of the system so that the developer spends as little time as possible understanding your situation. Your issue should reflect the:

repeatability of the problem - whether it is easy to repeat or happens randomly
steps to repeat - what you think caused the problem, ideally these steps should be repeated until they are as simple as possible and still cause the problem
desired outcome of the steps - that is, what you WANT to have happen
actual outcome of your steps - this is the essence of your problem

Probably updating the issue summary (the node body) would be a great place for this.

Here's a debug module you can enable into your vanilla Drupal Commerce install debug the bug.

It logs two hooks into watchdog under the 'debug' type.

These are the hooks:

function pe_commerce_commerce_payment_transaction_insert($transaction) {                                        
  watchdog('debug', 'pe_commerce_commerce_payment_transaction_insert (' . $transaction->order_id . ')');
  $order = commerce_order_load($transaction->order_id);
  $balance1 = commerce_payment_order_balance($order);
  $totals = array($transaction->currency_code => $transaction->amount);
  $balance2 = commerce_payment_order_balance($order, $totals);
  watchdog('debug', 'Transaction <pre>' . print_r($transaction, TRUE) 
                   . "</pre> Order <pre>" . print_r($order,  TRUE)
                   . "</pre>Balance1 = <pre>" . print_r($balance1, TRUE)
                   . '</pre>Balance 2<pre>' . print_r($balance2, TRUE) . '</pre>'
  );                                                                                               
}

function pe_commerce_commerce_payment_order_paid_in_full($order, $transaction) {
  watchdog('debug', 'pe_commerce_commerce_payment_order_paid_in_full (' . $transaction->order_id . ')');
}

Keep in mind, in order for Paid in Full to be called $balance1 has to be equal or less than Zero. Currently it's not applying the amount of the transaction against the balance of the order for reasons I've mentioned previously.

$balance2 is some logic I've added to show that we can in fact get this working with proper use of function calls.

I'm going to hack my own core to get this to move forward for the site I'm working on, but this needs to get resolved.

Getting another error now after a failed transaction (which was failed by bad code).

Now while I realize this error is caused by a different issue, I believe this is the cause of the problem.

When the transaction is saved into commerce_payment_transaction it initially has a revision_id of 0. Then after the commerce_payment_transaction_save() is finished, a revision is created & the entry in commerce_payment_transaction revision_id is updated.

This error is coming about because of a compilation error in pe_commerce_commerce_payment_transaction_insert() which is called before commerce_payment_transaction_save() is finished. Since pe_commerce_commerce_payment_transaction_insert() die()'d and commerce_payment_transaction_save() was never completed, the revision ID was never updated. Then when I tried to do another transaction, it tried to store it into commerce_payment_transaction table, but because there's already an entry with revision_id = 0, it fails.

Integrity constraint violation: 1062 Duplicate entry '0' for key 2: INSERT INTO {commerce_payment_transaction} (revision_id, uid, order_id, payment_method, instance_id, remote_id, message, message_variables, amount, currency_code, status, remote_status, payload, created, changed) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8, :db_insert_placeholder_9, :db_insert_placeholder_10, :db_insert_placeholder_11, :db_insert_placeholder_12, :db_insert_placeholder_13, :db_insert_placeholder_14); Array ( [:db_insert_placeholder_0] => 0 [:db_insert_placeholder_1] => 1 [:db_insert_placeholder_2] => 59 [:db_insert_placeholder_3] => authnet_aim [:db_insert_placeholder_4] => authnet_aim|commerce_payment_authnet_aim [:db_insert_placeholder_5] => 2161651563 [:db_insert_placeholder_6] => <b>Authorization and capture</b><br /><b>ACCEPTED:</b> This transaction has been approved.<br />AVS response: Address (Street) and five digit ZIP match<br />CVV match: Not Processed [:db_insert_placeholder_7] => a:0:{} [:db_insert_placeholder_8] => 49000 [:db_insert_placeholder_9] => USD [:db_insert_placeholder_10] => success [:db_insert_placeholder_11] => auth_capture [:db_insert_placeholder_12] => a:1:{i:1311952157;a:68:{i:0;s:1:"1";i:1;s:1:"1";i:2;s:1:"1";i:3;s:35:"This transaction has been approved.";i:4;s:6:"YCUA7Q";i:5;s:1:"Y";i:6;s:10:"2161651563";i:7;s:2:"59";i:8;s:8:"1x 60DAY";i:9;s:6:"490.00";i:10;s:2:"CC";i:11;s:12:"auth_capture";i:12;s:1:"1";i:13;s:0:"";i:14;s:0:"";i:15;s:0:"";i:16;s:6:"kjhkjh";i:17;s:5:"kjhkh";i:18;s:2:"kj";i:19;s:3:"kjh";i:20;s:2:"CA";i:21;s:0:"";i:22;s:0:"";i:23;s:19:"j0rd.spam@gmail.com";i:24;s:0:"";i:25;s:0:"";i:26;s:0:"";i:27;s:0:"";i:28;s:0:"";i:29;s:0:"";i:30;s:0:"";i:31;s:0:"";i:32;s:0:"";i:33;s:0:"";i:34;s:0:"";i:35;s:0:"";i:36;s:0:"";i:37;s:32:"1911C817FDB5C3A053BCCBADB435CDC4";i:38;s:1:"P";i:39;s:1:"2";i:40;s:0:"";i:41;s:0:"";i:42;s:0:"";i:43;s:0:"";i:44;s:0:"";i:45;s:0:"";i:46;s:0:"";i:47;s:0:"";i:48;s:0:"";i:49;s:0:"";i:50;s:8:"XXXX1111";i:51;s:4:"Visa";i:52;s:0:"";i:53;s:0:"";i:54;s:0:"";i:55;s:0:"";i:56;s:0:"";i:57;s:0:"";i:58;s:0:"";i:59;s:0:"";i:60;s:0:"";i:61;s:0:"";i:62;s:0:"";i:63;s:0:"";i:64;s:0:"";i:65;s:0:"";i:66;s:0:"";i:67;s:0:"";}} [:db_insert_placeholder_13] => 1311952157 [:db_insert_placeholder_14] => 1311952157 ) in drupal_write_record() (line 6861 of /home/www/powerengineercentral.ca/htdocs/includes/common.inc)

Here's a patch. I consider this a temporary solution as it doesn't solve the root issue.

Still requesting #15.

sub

I updated the description rfay with additional info. Re-activating this bug.

Thanks so much! Setting to CNR (#18) although j0rd says that is probably not the real fix.

-- too quick --

I have a similar problem with the condition 'Order balance comparison' attached to the event 'After saving a new commerce payment transaction' in a rule. The current payment transaction is not included in the balance comparison.

The problem seems to be caused by the database transaction processing. The rules processing is invoked after drupal_write_record has been called in DrupalCommerceEntitytController::save but drupal_write_record DOES NOT write data to disc it justs adds the record to the database transaction object. The payment transaction data is not committed to disc until the DatabaseTransaction is destroyed (and __destruct() called) when commerce_payment_transaction_save exits.

This seems to be a general problem to ensure the commerce data is committed to disc before rules processing is invoked.

I think #24 might have been a slight diversion. I changed my MySQL tables for commerce_payment_transaction and commerce_payment_transaction_revision from InnoDB to MyISAM since MyISAM does not support database transactions. This did not fix the problem although the data was now on disk before the rules and hooks handling was invoked.

The problem is now that the revision_id for the base table is not updated until after the rules and hooks have been run. This is still in DrupalCommerceEntitytController::save. The code

db_update($this->entityInfo['base table'])
            ->fields(array($this->revisionKey => $entity->{$this->revisionKey}))
            ->condition($this->idKey, $entity->{$this->idKey})
            ->execute();

which sets the revision id needs to be run before invoke. If the lines

$update_base_table = TRUE;

are replaced with the above the rules and hooks work.

This is a change to a core commerce class so I'm not sure if it will get committed just to solve this particular problem but I cannot see any other way around it.

In summary two changes are required:
1. Make sure your commerce database tables are MyISAM
2. Move the revision id update in the base table to before the rules and hooks are invoked

Patch for #25.

I agree we should run the hooks after the full update has been performed. That's actually a bug in my initial revision support patch :)

Better patch attached, please don't credit me.

Committed Damien's patch for this. Tests worked fine. On a side note, some of the monkeying we're doing for messages in the checkout form are the reason you don't ever see messages displayed. I tested by using watchdog() in a custom PHP action.

Damien, given InnoDB is the default mySQL engine for D7 this functionality is still 'broken' without changing the table to MyISAM. Is there a plan to handle this?

It sounds like that's unrelated. I didn't do any database adjustments and it worked just fine in my testing w/ InnoDB tables. As such I don't think there's anything more to do here. With the latest patch on InnoDB can you provide me with a set of steps to reproduce an error? If so, it might be a separate issue.

Also, I should've added that I'll be addressing the missing messages in a follow-up issue.

I have this problem too, hook_commerce_payment_order_paid_in_full does not get called, applied patch in #18, but it still doesn't work.
commerce kickstart profile - commerce 1.1

I've just updated a site to commerce 7.x-1.2 and this problem has re-emerged! It seems when a transaction is saved the order_balance calculation retrieves out of date transaction status information when calculating how much has been paid.

Looking at the code there has been a new section added after the previous patch in commerce.controller.inc:

$this->invoke($op, $entity);

// Update the static cache so that the next entity_load() will return this
// newly saved entity.
$this->entityCache[$entity->{$this->idKey}] = $entity;

I am concerned that the cache is set AFTER the hooks are invoked and therefore any transaction reloads carried out in the hooks (as is done in commerce_payment_order_balance) get old entity cache data rather than the new entity.

This seems to be a new level of caching which I don't fully undertand yet but could it be a possible cause of hook_commerce_payment_order_paid_in_full() not firing?

Yup. This was actually fixed in #1427780: hook_commerce_payment_order_paid_in_full() does NOT fire due to DrupalCommerceEntityController::save bug and will be released in Commerce 7.x-1.3

I had an issue with "hook_commerce_payment_order_paid_in_full" that sometimes hasn't been called.
I think it's since we've updated rules module.

I've just updated to Commerce from 7.x-1.2 to 7.x-1.3, and it rocks !
Thanks a lot !!

ps: just for information, no long ago, we've updated Drupal core too (from 7.12 to 7.14)

Glad to hear it.

Updated description as per rfay request.