CiviCRM 4.4.4 mishandling accepted CC transactions in Utils.php

[mdlueck]

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);

rrrr? I was attempting to provide you with the requested output from here:

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 :-(

So should I add a dump of specifically $contribution in addition to each debug_backgrace() in order to see where working transactions end up getting the fields in the array populated and where busted transactions are probably derailing due to the fields never getting correctly populated, or...

[Eileen]

Sorry - I'd moved on from that  - Do you want to jump on IRC

Bascially I think question we *should* see $result with trxn_id set right after this line - so we should output $result there & check
 
https://github.com/civicrm/civicrm-core/blob/4.4/CRM/Contribute/BAO/Contribution/Utils.php#L230


& we should check that it STILL has trxn_id set just before this line
https://github.com/civicrm/civicrm-core/blob/4.4/CRM/Contribute/BAO/Contribution/Utils.php#L287

That should effectively segment the code into 3 portions & we will know which of those 3 we should focus on (ie. before the first check, between the 2 checks or after the second one)

[mdlueck]

FYI: I am presently in IRC.

& we should check that it STILL has trxn_id set just before this line

In which array, $result or $contribution?

I have tested that the fields are populated in $result consistently from "top to bottom" of Utils.php.

For the more complex transactions, it appears not all of the necessary fields are making the hop from $result into $contribution.

And I have not been able to understand the code fully enough to see where the train wreck is happening.

I am thankful,

[mdlueck]

Greetings Eileen,

Thank you for working with me via IRC yesterday. I took a fresh look at the problem this morning. I found the LOC I was thinking of before and then could not find within Utils.php:

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

This LOC appears to be passed both the form which data coming back from the CC gateway was entered into and also the raw $result array which should still contain the response from the CC gateway.

I was able to get the Confirm.php file to dump debug output this morning. I added a couple of additional variable dumps to what you had already requested, and I got both outputs this time. Whatever... 

It appears that Confirm.php has not received the $result array object from Utils.php. What does it look like to you?

I am thankful,

[mdlueck]

Greetings Eileen,

I see what you mean about Confirm.php getting called a couple of times. The place I was first checking ended up not being the first call to Confirm.php.

I went through Utils.php and added some strategic spot checking of variables with meaningful names in the log. Please review the attached and advise what would be still helpful based on what I have attached.

P.S. Our server happens to run PHP from the Hardened PHP project. http://www.hardened-php.net/ Which PHP fork is on the server which hosts the Drupal-CiviCRM test site, perhaps the non Hardened fork? I wonder if something in the CiviCRM code is not compatible with Hardedned PHP?

I am thankful,

[mdlueck]

Greetings Eileen,

I thought to capture the same type of trace output from a working / completing straight-up donation transaction. Please find it attached here. Yes, this transaction got to "Completed" status on the Contribution Dashboard.

Perhaps you can compare this trace and the trace just prior to see where the more complicated transactions are going wrong?

Please let me know what more I can do to assist in finding / resolving this nagging error. I could not get the trace file to attach to the Civi forum for some reason this time, so I uploaded it to our website in a hurry.

http://www.lueckdatasystems.com/pub/clients/CIR/CiviCRM_PJ_DebugOutputSimpleDonation1.txt

I am thankful,

[mdlueck]

Greetings Eileen,

All right, I think we are getting somewhere with this CiviCRM inconsistency. I used grep to isolate out the various debug spots and each time the value trxn_result_code is seen in the two last traces. Grep output is as follows:

CiviCRM_PJ_DebugOutputSimpleDonation1.output.trace.txt

Code: [Select]

Utils.php result just after payment->doDirectPayment() Spot 2B
    [trxn_result_code] => 00
Utils.php result just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
    [trxn_result_code] => 00
Utils.php form just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
            [trxn_result_code] => 00
Confirm.php contribParams just after setting trxn_id
    [trxn_result_code] => 00
Confirm.php result just after setting trxn_id
    [trxn_result_code] => 00
Confirm.php contribParams
    [trxn_result_code] => 00
Confirm.php contribution
    [trxn_result_code] => 00
Utils.php result just after form->postProcessPremium() Spot 3B
    [trxn_result_code] => 00
Utils.php contribution just after form->postProcessPremium() Spot 3B
    [trxn_result_code] => 00

Utils.php.Michael5.output.trace.txt

Code: [Select]

Utils.php result just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 2
Utils.php form just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 2
Confirm.php contribParams just after setting trxn_id
Confirm.php result just after setting trxn_id
Confirm.php contribParams
Confirm.php contribution
    [trxn_result_code] =>
Utils.php result just after payment->doDirectPayment() Spot 2B
    [trxn_result_code] => 00
Utils.php result just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
    [trxn_result_code] => 00
Utils.php form just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
            [trxn_result_code] => 00
Utils.php result just after form->postProcessPremium() Spot 3B
    [trxn_result_code] => 00
Utils.php contribution just after form->postProcessPremium() Spot 3B
    [trxn_result_code] =>

Now, the more complex transaction type hits two different spots the processContribution class method. The Spot 2 is what is extra in the more complex transaction, and the trxn_result_code value is not set in Spot 2. After that, then it does go through Spot 3, the trxn_result_code there is populated, however at the end, the contribution object which is what is returned by Utils.php still does not have the trxn_result_code value populated.

What do you think?

I am thankful,

[mdlueck]

Greetings Eileen,

Great excellent news indeed!!!    The problem which has been plaguing us since CiviCRM 2.0.7 is resolved in CiviCRM 4.5.x!!! Wow wow wow!!! Thank you Eileen for digging through the membership join code!!!

I just mocked up the same sort of debug code I was testing with before on 4.4.6. I noticed a big huge chunk missing from civicrm/CRM/Contribute/Form/Contribution/Confirm.php dealing with "// first create the contribution record" so what code has been deleted, I could no longer place debug code in what is no longer there... 

Debug output from a successful new member join on CiviCRM 4.5.2 was as follows:

Code: [Select]

$ grep -e "\[trxn_result_code\]" -e Utils.php -e Confirm.php CiviCRM_PJ_DebugOutput452NewMemberJoin1.txt
Utils.php result just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 2
Utils.php form just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 2
Confirm.php contribParams
Confirm.php contribution
    [trxn_result_code] =>
Utils.php result just after payment->doDirectPayment() Spot 2B
    [trxn_result_code] => 00
Utils.php result just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
    [trxn_result_code] => 00
Utils.php form just before CRM_Contribute_Form_Contribution_Confirm::processContribution Spot 3
            [trxn_result_code] => 00
Utils.php result just after form->postProcessPremium() Spot 3B
    [trxn_result_code] => 00
Utils.php contribution just after form->postProcessPremium() Spot 3B
    [trxn_result_code] =>

We are, for the first time ever, seeing new member join emails go out... so have to scramble scramble get those templates working properly.

Thank you, thank you, thank you, Elieen!!!! 

[Eileen]

Actually Dave & Monish wound up doing a fair bit of work on that code too - but glad it's working!

[mdlueck]

Oh boy... the beastly nonsense bug has come back!!! 

This site has two payment gateways enabled: PayJunction and PayPal. A membership join came in specifying PayPal, which that transaction got stuck in pending mode, no emails went out, and so on...

And now PayJunction membership joins gets stuck in Pending state the same way they had been since day one.

Where do we go from here?

Oh, and after successfully getting to CiviCRM 4.5.x, I then ran a DB schema verify on the DB, based on this page:

"Ensuring Schema Integrity on Upgrades"
http://wiki.civicrm.org/confluence/display/CRMDOC/Ensuring+Schema+Integrity+on+Upgrades

So the DB schema is 100% verified. We only had a few custom schema tables... perhaps six tables total.

What in the world could a membership join via PayPal that would cause so much lateral damage?

I am thankful,