CiviCRM 4.4.4 mishandling accepted CC transactions in Utils.php

[mdlueck]

Greetings,

Simple CiviCRM donation contribution transactions process through to successful completion on a client's site.

More complex CiviCRM site Membership join transactions which are combined, consisting of:
1) CiviMembership - as it is a website with paid membership component
2) CiviContribution - to collect the funds
3) CiviProfile - to gather contact information (In production, this is used to provision the joining member with a Drupal account as well, though I am not testing with that additional item.)

These more complex transactions we see the charge being accepted by the gateway company, PayJunction.

Somehow CiviCRM in source file: ./CRM/Contribute/BAO/Contribution/Utils.php is mishandling the accepted CC charge, leaving the CiviContribution record in "Pending (Incomplete Transaction)" state.

I have attached the cleaned up Apache Error log of two test transaction - one pass / one fail.
Also attached is the one and only modified PHP file which I have inserted logging into.

I notice that in the two places I enumerate through array objects, the first point in the failing transactions has values trxn_id and trxn_result_code populated, while by the second point the values have been blanked out. Since the gateway returned those values, why is CiviCRM loosing them during the more complicated transactions? I believe this to be illustrating the reason for the transactions not completing properly.

Please assist us in resolving this CiviCRM mishandling of accepted CC transactions.

I am thankful,

[Eileen]

I would patch your codebase like this & then check your civicrm log for debug output.

(note the first line of this patch is just a fix that *should* be done in Payjunction - I submitted the same change for eWay yesterday - but I doubt it is significant)

diff --git a/CRM/Core/Payment/PayJunction.php b/CRM/Core/Payment/PayJunction.php
index 7080288..219d8ea 100644
--- a/CRM/Core/Payment/PayJunction.php
+++ b/CRM/Core/Payment/PayJunction.php
@@ -53,7 +53,7 @@
    * @static
    *
    */
-  static function &singleton($mode, &$paymentProcessor) {
+  static function &singleton($mode, &$paymentProcessor, &$paymentForm = NULL, $force = false) {
     $processorName = $paymentProcessor['name'];
     if (self::$_singleton[$processorName] === NULL) {
       self::$_singleton[$processorName] = new CRM_Core_Payment_PayJunction($mode, $paymentProcessor);
@@ -160,7 +160,9 @@
 
     // get an pjpgResponse object
     $pjpgResponse = $pjpgHttpPost->getPJpgResponse();
-
+    CRM_Core_Error::debug('txnarray', $txnArray, TRUE);
+    CRM_Core_Error::debug('pjpgRequest', $pjpgRequest, TRUE);
+    CRM_Core_Error::debug('pjpgResponse', $pjpgResponse, TRUE);
     if (self::isError($pjpgResponse)) {
       return self::error($pjpgResponse);
     }

[mdlueck]

Very nice, Eileen! Much better output dump than dealing with the Apache error log method.

Please find attached the output of a failed test site membership join transaction.

I see, per usual PJ answering back:
[dc_response_message] => APPROVAL PJ20AP

I am thankful,

[Eileen]

so, in fact the trxn_id should be correctly populated at this point from what you say...

diff --git a/CRM/Core/Payment/PayJunction.php b/CRM/Core/Payment/PayJunction.php
index 7080288..e534bd3 100644
--- a/CRM/Core/Payment/PayJunction.php
+++ b/CRM/Core/Payment/PayJunction.php
@@ -53,7 +53,7 @@
    * @static
    *
    */
-  static function &singleton($mode, &$paymentProcessor) {
+  static function &singleton($mode, &$paymentProcessor, &$paymentForm = NULL, $force = false) {
     $processorName = $paymentProcessor['name'];
     if (self::$_singleton[$processorName] === NULL) {
       self::$_singleton[$processorName] = new CRM_Core_Payment_PayJunction($mode, $paymentProcessor);
@@ -160,7 +160,9 @@
 
     // get an pjpgResponse object
     $pjpgResponse = $pjpgHttpPost->getPJpgResponse();
-
     if (self::isError($pjpgResponse)) {
       return self::error($pjpgResponse);
     }
@@ -176,7 +178,7 @@
     $params['trxn_result_code'] = $pjpgResponse['dc_response_code'];
     $params['trxn_id'] = $pjpgResponse['dc_transaction_id'];
     $params['gross_amount'] = $params['amount'];
-
+    CRM_Core_Error::debug('params', $params, TRUE);
     return $params;
   }
   // end function doDirectPayment

Do you have 'separate payment' configured on your contribution page - ie

"
x
Separate Payment

Check this box if you are including both Membership Signup/Renewal AND a Contribution Amount section, AND you want the membership fee to be handled as a separate transaction.

With this configuration, the membership fee is automatically charged, and users have an option to make an additional contribution (two separate payment transactions will be generated).

The contribution amount covering the membership fee will use the financial type configured with the selected membership type (see the membership types configuration tool to review those settings). Any additional contribution will use the financial type configured for this online contribution page.

If this option is NOT checked and you include a Contribution Amount section, then a single transaction is processed for their contribution amount which must at least cover the selected membership fee.

NOTE: This option is NOT available for PayPal Website Payments Standard and Google Checkout."

I believe separate payment may work for ? Paypal Pro? but would not expect it to work for PayJunction

[mdlueck]

Do you have 'separate payment' configured on your contribution page - ie

The site membership join contribution page is configured thusly:

Title tab:
Financial Type: Membership Dues
Goal Amount/Date fields: All blank
[X] Use a confirmation page?
[X] Is this Online Contribution Page Active?

Amount:
Execute real-time monetary transactions [X]
Payment Processor: [X] Pay Junction Test Gateway

Memberships:
[X] Membership Section Enabled?
Membership Types: Weekly / Monthly / Yearly
[X] Require Membership Signup
[ ] Separate Membership Payment
[X] Display Membership Fee

Receipt:
Settings to email a receipt

Profiles:
For now just using the CiviCRM default "Name and Address" profile. In production we use a custom profile which provisions a Drupal account in addition to all else.

I will get to providing your requested trace ASAP. Posting these details first for now. Thank you so much!

[mdlueck]

Greetings Eileen,

Odd, no debug output to the web browser this time. The new test transaction still got stuck in pending state.

I got the dreaded green box stating:

Your contribution has been submitted to PayJunction Test Gateway for processing. Please print this page for your records.
An email receipt will be sent to emailaddywashere once the transaction is processed successfully.

patch gripped about the end of your diff, so I had to manually patch it myself. I will attach it below to be sure the patch was what you intended. It made sense to me.

I am thankful,

[Eileen]

If there is no output to the browser or the log file it might not be getting that far - ie.  it could be exiting in one of these return statements - you might want to add some debug into them

    if (self::isError($pjpgResponse)) {
      return self::error($pjpgResponse);
    }

    /* Check for application errors */

    $result = self::checkResult($pjpgResponse);
    if (is_a($result, 'CRM_Core_Error')) {
      return $result;
    }

[mdlueck]

Greetings Eileen,

No worries... I began fresh on it this morning and was able to get it to go all of the way through the module. Sanitized output attached.

And yes, in the Civi Contribution Dashboard, this test transactions is stuck at "Pending (Incomplete Transaction)" state.

I would think this to indicate it not a PJ specific file is where the transaction goes wrong... like I started this post it seemed to me to go wrong in file: ./CRM/Contribute/BAO/Contribution/Utils.php

I am thankful,

[mdlueck]

Greetings Eileen,

I took the liberty of using the debug trick you are using in your modifications to obtain debug output from Utils.php. The diff and output is attached.

I did leave the corrected syntax in place in the PayJunction.php we had been testing with when I ran this Utils.php test. That was the only other mod to stock CiviCRM 4.4.4 D6 code.

The output clearly shows the trxn_id and trxn_result_code populated in the $result array coming back from the $payment->doDirectPayment() call, then the same fields have gotten lost by the time the transaction is in the $contribution object which that goes in object $membershipResult[1] and is returned by Utils.php

I am thankful,

[Eileen]

OK - you are going to need to add a

CRM_Core_Error::debug('backtrace', debug_backtrace()));

& then go through adding your debug all the way along until you figure out when it stopped being there :-(

[mdlueck]

Greetings Eileen,

About debugging this file: ./CRM/Contribute/BAO/Contribution/Utils.php

You were aware that it appears $result contains the return from the CC gateway, while $contribution is ultimately what gets returned by Utils.php.

I do not see a reference to fields trxn_id and trxn_result_code getting transferred from $result to $contribution. Yet the way I understand the code is that those values need to get transferred from $result to $contribution. Did I interpret correctly?

I will experiment with strategically placing some debug_backtrace() LOCs to see what I am able to learn about the situation.

Oh... I just took another look at the code. Is the code populating an HTML form from $result, then populating $contribution from the HTML form, perhaps?

I am thankful,

[Eileen]

So,

I think you are saying that it gets to here & calls this function

https://github.com/civicrm/civicrm-core/blob/4.4/CRM/Contribute/BAO/Contribution/Utils.php#L287


At the point when the function is called is $result['trxn_id'] correctly populated or not?

[mdlueck]

So,

I think you are saying....

OK, since you shared a method of linking to the source code directly, I will utilize such to clarify my last post.

Oh... I just took another look at the code. Is the code populating an HTML form from $result, then populating $contribution from the HTML form, perhaps?

[Is the code populating an HTML form from $result]
https://github.com/civicrm/civicrm-core/blob/4.4/CRM/Contribute/BAO/Contribution/Utils.php#L264

[$contribution from the HTML form]
............ fiddlesticks... I cannot spot the LOC I thought was reading the form and populating the $contribution field with the trxn_id. I do not see an explicit setting of that trxn_id field within $contribution. "How does it ever get there?!" gggrrr...

I suppose I will blindly sprinkle insert the LOC you suggested and see if I can uncover something useful.

I am thankful,

[mdlueck]

Greetings Eileen,

I sprinkled your suggested LOC around the Util.php file, sent a test membership join transaction, and captured over 14M worth of trace data.

I suspect, however, it did not dump the $contribution array as the trxn_id and trxn_result_code fields I had been keeping an eye on in my sleuthing are always populated.

I have attached my diff to the Utils.php file as compared to v4.4.4 from CiviCRM official. Could you please double check what I attempted and comment as to if the $contribution array should have been enumerated or not?

I am thankful,

[Eileen]

Yeah - that will give you a lot of info - you want to just check the variables e.g

CRM_Core_Error::debug('contribution at line x', $contribution);