Paypal transactions not completing.

[securit]

Hi,

I have a site that has been working for several years successfully. I recently upgraded to v154 and now am experiencing strange problems with my transactions. Some transactions appear to successfully complete at PayPal (I get an email from PayPal to say that the purchase is approved), but I see nothing in the ZenCart orders log for the product.

I have also turned on PayPal logging and I think I can see the transactions in the paypal transactions logs working as expected.

How on earth do I debug this one and get to the bottom of the problem. Its like the Order doesn't exist on the Zencart side of things and yet the Paypal request appears to work fine.

Thanks in advance for any suggestions or recommendations.

[mc12345678]

Which paypal method is being used? Is it paypal standard? Did you try uninstalling the method and then reinstall/reenable?

[Merlinpa1969]

Is this due to the upgrades paypal announced, regarding SSL ( requiring sha2 ) and RC4 cipher

[DrByte]

Which paypal method is being used? Is it paypal standard?

Agreed. Answers to those questions are necessary in order to help.
Also, in the /logs/ folder are there any myDebug-xxxxx.log files being generated at the same time as the PayPal-xxxxxxx.log files? What's in them? What's in the PayPal-xxxxx.log files?

[securit]

There are no myDebug-xxxxx.log files.

I have not tried disabling and reinstalling the PayPal IPN. Its running PalPal Express checkout rev1.5.4

The paypal ipn log for a failed transaction is as follows (Some customer info replaced with X's):
Jun 01 2015 3:24 -- IPN PROCESSING INITIATED.
*** Originating IP: 173.0.XX.X
*** Browser/User Agent: PayPal IPN ( https://www.paypal.com/ipn )

Jun 01 2015 15:24 -- Breakpoint: 0 - Initializing debugging.

Jun 01 2015 15:24 -- Breakpoint: Flag Status:
isECtransaction = 1
isDPtransaction = 0

Jun 01 2015 15:24 -- IPN INFO - POST VARS received (sorted):
Array
(
[address_city] => christchurch
[address_country] => New Zealand
[address_country_code] => NZ
[address_name] => XXXXXX XXXXXXX
[address_state] => SOUTH ISLAND
[address_status] => unconfirmed
[address_street] => XX XXXXXX XXXXXXX Merivale
[address_zip] => XXXX
[charset] => windows-1252
[custom] => EC-1406-1433129082
[first_name] => XXXXXX
[invoice] => 1406-1433129082-[XXXXXXXXX]
[ipn_track_id] => 17047a7230eb4
[item_name1] => Freeform Pendant [1165]
[item_number1] => 1641
[last_name] => XXXXXXX
[mc_currency] => NZD
[mc_fee] => 5.50
[mc_gross] => 148.50
[mc_gross_1] => 140.00
[mc_handling] => 0.00
[mc_handling1] => 0.00
[mc_shipping] => 8.50
[mc_shipping1] => 0.00
[notify_version] => 3.8
[num_cart_items] => 1
[payer_email] => XXXXXXXX######################
[payer_id] => XAJXXXXXXXX
[payer_status] => unverified
[payment_date] => 20:24:44 May 31, 2015 PDT
[payment_fee] =>
[payment_gross] =>
[payment_status] => Completed
[payment_type] => instant
[protection_eligibility] => Ineligible
[quantity1] => 1
[receipt_id] => 3244-8796-XXXX-XXXX
[receiver_email] => [email protected]
[receiver_id] => SWXD4VWFXXXXX
[residence_country] => NZ
[tax] => 0.00
[tax1] => 0.00
[transaction_subject] =>
[txn_id] => 7U964772C481XXXXX
[txn_type] => cart
[verify_sign] => AAAD9b9g7ioAHQ6Y7QY8QY1C2SuTA-FQ02wPLEmRgXXXXXXljnYuz96f
)


Jun 01 2015 15:24 -- IPN INFO - POST VARS to be sent back (unsorted) for validation (using CURL):
To: www.paypal.com:80
Array
(
[cmd] => _notify-validate
[mc_gross] => 148.50
[invoice] => 1406-1433129082-[XXXXXXXXXX]
[protection_eligibility] => Ineligible
[address_status] => unconfirmed
[item_number1] => 1641
[payer_id] => XAJXT9ZXXXXX
[tax] => 0.00
[address_street] => XX XXXXXXXXX XXX Merivale
[payment_date] => 20:24:44 May 31, 2015 PDT
[payment_status] => Completed
[charset] => windows-1252
[address_zip] => XXXX
[mc_shipping] => 8.50
[mc_handling] => 0.00
[first_name] => XXXXX
[mc_fee] => 5.50
[address_country_code] => NZ
[address_name] => XXXXX XXXXXX
[notify_version] => 3.8
[custom] => EC-1406-14331XXXXX
[payer_status] => unverified
[address_country] => New Zealand
[num_cart_items] => 1
[mc_handling1] => 0.00
[address_city] => christchurch
[verify_sign] => AAAD9b9g7ioAHQ6Y7QY8QY1C2SuTA-FQXXXXXXXXXXXXXXnYuz96f
[payer_email] => [email protected]
[mc_shipping1] => 0.00
[tax1] => 0.00
[txn_id] => 7U964772C481XXXX
[payment_type] => instant
[last_name] => XXXXXX
[address_state] => SOUTH ISLAND
[item_name1] => Freeform Pendant [1165]
[receiver_email] => [email protected]
[payment_fee] =>
[quantity1] => 1
[receiver_id] => SWXD4VWXXXXX
[txn_type] => cart
[mc_gross_1] => 140.00
[mc_currency] => NZD
[residence_country] => NZ
[receipt_id] => 3244-8796-XXXX-XXXX
[transaction_subject] =>
[payment_gross] =>
[ipn_track_id] => 17047a7230eb4
)


Jun 01 2015 15:24 -- CURL OPTS: Array
(
[10002] => https://www.paypal.com/cgi-bin/webscr
[47] => 1
[10015] => cmd=_notify-validate&mc_gross=148.50&invoice=1406-1433129082-%5BXXXXXXXX%5D&protection_eligibility=Ineligible&address_status=unconfirmed&item _number1=1641&payer_id=XAJXT9ZXXXXXX&tax=0.00&address_street=XX+XXXXXXX+XXX%0D%0 AMerivale&payment_date=20%3A24%3A44+May+31%2C+2015+PDT&payment_status=Completed& charset=windows-1252&address_zip=XXXX&mc_shipping=8.50&mc_handling=0.00&first_name=XXXXX&mc_fee= 5.50&address_country_code=NZ&address_name=XXXXXX+XXXXXX&notify_version=3.8&custo m=EC-1406-143312XXXXX&payer_status=unverified&address_country=New+Zealand&num_cart_items=1 &mc_handling1=0.00&address_city=christchurch&verify_sign=AAAD9b9g7ioAHQ6Y7XXXXXX XXXXTA-FQ02wPXXXXXXXZZtljnYuz96f&payer_email=XXXXXX%40XXXXXX.com&mc_shipping1=0.00&tax1 =0.00&txn_id=7U964772C4811772D&payment_type=instant&last_name=XXXXXX&address_sta te=SOUTH+ISLAND&item_name1=Freeform+Pendant+%5B1165%5D&receiver_email=XXXXXXXX%4 0XXX.com&payment_fee=&quantity1=1&receiver_id=SWXD4VWXXXXX4&txn_type=cart&mc_gro ss_1=140.00&mc_currency=NZD&residence_country=NZ&receipt_id=3244-8796-XXXX-XXXX&transaction_subject=&payment_gross=&ipn_track_id=17047a7230eb4
[13] => 45
[78] => 30
[41] => 0
[42] => 0
[52] => 0
[19913] => 1
[75] => 1
[74] => 1
[84] => 2
[10018] => Zen Cart(R) - IPN Postback
)


Jun 01 2015 15:24 -- CURL response: VERIFIED

Jun 01 2015 15:24 -- IPN INFO (cl) - Confirmation/Validation response VERIFIED

Jun 01 2015 15:24 -- Breakpoint: 1 - Collected data from PayPal notification

Jun 01 2015 15:24 -- Breakpoint: 2 - Validated transaction components

Jun 01 2015 15:24 -- Breakpoint: 3 - Communication method verified

Jun 01 2015 15:24 -- IPN NOTICE :: Could not find matched txn_id record in DB. Therefore is new to us.

Jun 01 2015 15:24 -- Breakpoint: 4 - Details: txn_type=unique ordersID = 0 IPN_id=0

Relevant data from POST:
txn_type = unique
parent_txn_id = None
txn_id = 7U964772C4811772D

Jun 01 2015 15:24 -- Breakpoint: 5 - Transaction type (txn_type) = cart [parentLookup=unique]

Jun 01 2015 15:24 -- Breakpoint: 5 - midstream checkpoint

Jun 01 2015 15:24 -- Breakpoint: 5 - Record does not need to be processed since it is not new and is not an update. See earlier notices. Processing aborted.

[RodG]

I have not tried disabling and reinstalling the PayPal IPN. Its running PalPal Express checkout rev1.5.4

I suggest that this be the 1st step.

Also check that you have the latest (or correct) version of the /ipn_main_handler.php file.

Your debug output shows that something is 'confused'
Jun 01 2015 15:24 -- IPN NOTICE :: Could not find matched txn_id record in DB. Therefore is new to us.
and
Jun 01 2015 15:24 -- Breakpoint: 5 - Record does not need to be processed since it is not new and is not an update

It is the ipn_main_handler.php file that is producing both these outputs, which suggests (to me) that there is a data/version mismatch between this file and the /module/payment/paypal* file(s). I can't determine which one(s) it would be though.

Cheers
RodG

[DrByte]

It is the ipn_main_handler.php file that is producing both these outputs

Yes, it is. And the IPNs are merely indicators that a transaction happened at PayPal, and PayPal is notifying the store.

The problem is that the store doesn't have record of the order, and the IPN handler is merely confirming the same fact that the OP posted initially.

which suggests (to me) that there is a data/version mismatch between this file and the /module/payment/paypal* file(s).

Can you explain how you came to that conclusion?



I think the real problem here is that something is happening in the store's checkout operations, AFTER the PayPal steps occur, and that "something" is causing the PHP code to abort before the data is saved and emails are sent, etc.
Tests I'd do include going through a full checkout purchase and seeing what exactly does happen, as far as the customer sees.
And also, turn on the PayPal debug logging, and look at (and post) the PayPal_xxxxxx.log files for the specific transaction, not the ipn_xxxxx.log files.

[RodG]

The problem is that the store doesn't have record of the order, and the IPN handler is merely confirming the same fact that the OP posted initially.

Exactly, and this is/was reflected in these two lines.

Jun 01 2015 15:24 -- IPN NOTICE :: Could not find matched txn_id record in DB. Therefore is new to us.
Jun 01 2015 15:24 -- Breakpoint: 4 - Details: txn_type=unique ordersID = 0 IPN_id=0

The txn_type=unique is used to set the $new_record_needed flag, as such:

line#200    $new_record_needed = ($txn_type == 'unique' ? true : false);

The code then flows down to the midsream breakpoint..

line#261

      ipn_debug_email('Breakpoint: 5 - midstream checkpoint');
      if (!(substr($txn_type,0,8) == 'pending-' && (int)$ordersID <= 0) && !($new_record_needed && $txn_type == 'echeck-cleared') && $txn_type != 'unique' && $txn_type != 'echeck-denied' && $txn_type != 'voided') {

Which fails/passes the checks and produces the "since it is not new" output on line#262

        ipn_debug_email('Breakpoint: 5 - Record does not need to be processed since it is not new and is not an update. See earlier notices. Processing aborted.');
        break;
      }

Can you explain how you came to that conclusion?

Now the way *I* see it, is that the code should never have gotten to line#262 on account of the $new_record_needed being set (How could the record new and not new at the same time?).
Granted, I could be reading that code wrong. - multiple nots and ands tend to confuse me unless I write them myself ;-)

As there are no further debug outputs I am assuming the code has simply died or exited at this point, and the "new record" simply isn't being created. Either way, I didn't follow this path any further, on the basis that *something* was amiss to cause the contradictory debug output.

I then compared this code with the code from an older version of zencart and noted a number of differences in the testing/checking being performed, and "jumped" to the conclusion that the OP *could* be using the older code (that still has the same debug outputs), and if that were the case, then updating to the newer/current code could invoke a solution.

I think the real problem here is that something is happening in the store's checkout operations, AFTER the PayPal steps occur, and that "something" is causing the PHP code to abort before the data is saved and emails are sent, etc.

This also makes a lot of sense. The only difference being that you are figuring something is *happening* to cause this, while my assumption is/was the $new_record_needed flag/test has somehow gone haywire causing the checkout operations to not realise that a new record needs to be created in the 1st place.

Tests I'd do include going through a full checkout purchase and seeing what exactly does happen, as far as the customer sees.
And also, turn on the PayPal debug logging, and look at (and post) the PayPal_xxxxxx.log files for the specific transaction, not the ipn_xxxxx.log files.

As would I, but currently we/I only have the debug output presented here, and a relatively cursory look at the code that would produce the output results given.

Then not being able to make an accurate diagnosis (other than *something* is amiss) and assuming that
"PalPal Express checkout rev1.5.4" is the current/latest version of the module(s), the only other real possibility is back to the ipn_handler.

I 'ignored' (or didn't consider) the possibility of the problem being with the checkout functions themselves, on the basis that this was a 'sometimes' problem (I think I may have misread that though), or that if it was a problem with the checkout functions it would *probably* affect all all checkouts regardless of payment method, and probably it would be all the time, rather than 'sometimes'

Admittedly, I've had to make an assumption or two (and a little bit of guesswork) to come to this 'conclusion', but right or wrong, that is how I got there.

Cheers
RodG

[securit]

Hi,

I downloaded a copy of the source and did a file comparison of every paypal file in the in the /includes/modules/payment.... directory and subdirectories and the ipn_main_handler.php files. They were exactly the same, so the problem has not been caused by a difference in the files. The weirdest thing is that some of the transactions complete successfully. I could accept that there was something wrong with the implementation if it failed 100% of the time... but it doesnt.

[securit]

OK, so the reason why I thought that the paypal log didn't show the problem was that I looked at the transactions and I found one that looks the same (ie has the same errors etc) but that processed through correctly. I'm still at a loss as to how to debug this situation as the return results are so inconsistent.

Jun 05 2015 10:39 -- IPN PROCESSING INITIATED.
*** Originating IP: 173.0.81.1
*** Browser/User Agent: PayPal IPN ( https://www.paypal.com/ipn )

Jun 05 2015 22:39 -- Breakpoint: 0 - Initializing debugging.

Jun 05 2015 22:39 -- Breakpoint: Flag Status:
isECtransaction = 1
isDPtransaction = 0

Jun 05 2015 22:39 -- IPN INFO - POST VARS received (sorted):
Array
(
[address_city] => Amberley
[address_country] => New Zealand
[address_country_code] => NZ
[address_name] => XXXXXX XXXXXX
[address_state] => Amberley
[address_status] => unconfirmed
[address_street] => XXXXX XXXXXX XXXXX
XXXXX
[address_zip] => 7481
[charset] => windows-1252
[custom] => EC-1412-1433500757
[first_name] => XXXXX
[invoice] => 1412-1433500757-[XXXXXX]
[ipn_track_id] => 21b7645ac8afb
[item_name1] => Greenstone Toki [1734]
[item_number1] => 4005
[last_name] => XXXXX
[mc_currency] => NZD
[mc_fee] => 6.18
[mc_gross] => 168.50
[mc_gross_1] => 160.00
[mc_handling] => 0.00
[mc_handling1] => 0.00
[mc_shipping] => 8.50
[mc_shipping1] => 0.00
[notify_version] => 3.8
[num_cart_items] => 1
[payer_email] => XXXX.XXXXXX######################
[payer_id] => UT3LNSAFG6QV6
[payer_status] => unverified
[payment_date] => 03:39:21 Jun 05, 2015 PDT
[payment_fee] =>
[payment_gross] =>
[payment_status] => Completed
[payment_type] => instant
[protection_eligibility] => Ineligible
[quantity1] => 1
[receipt_id] => 2818-7805-8686-3347
[receiver_email] => [email protected]
[receiver_id] => SWXD4VWFT5AB4
[residence_country] => NZ
[tax] => 0.00
[tax1] => 0.00
[transaction_subject] =>
[txn_id] => 1KT33284H2515141A
[txn_type] => cart
[verify_sign] => AOHgDv0QV7M8TthilveJDmE5eO6iARlJP67DPXX9Ps4Cdz5V7Y34RVuh
)


Jun 05 2015 22:39 -- IPN INFO - POST VARS to be sent back (unsorted) for validation (using CURL):
To: www.paypal.com:80
Array
(
[cmd] => _notify-validate
[mc_gross] => 168.50
[invoice] => 1412-1433500757-[XXXXXXXX]
[protection_eligibility] => Ineligible
[address_status] => unconfirmed
[item_number1] => 4005
[payer_id] => UT3LNSAFG6QV6
[tax] => 0.00
[address_street] => XX XXXXXX XX
XXXXXX
[payment_date] => 03:39:21 Jun 05, 2015 PDT
[payment_status] => Completed
[charset] => windows-1252
[address_zip] => 7481
[mc_shipping] => 8.50
[mc_handling] => 0.00
[first_name] => XXXXX
[mc_fee] => 6.18
[address_country_code] => NZ
[address_name] => XXXX XXXXX
[notify_version] => 3.8
[custom] => EC-1412-1433500757
[payer_status] => unverified
[address_country] => New Zealand
[num_cart_items] => 1
[mc_handling1] => 0.00
[address_city] => Amberley
[verify_sign] => AOHgDv0QV7M8TthilveJDmE5eO6iARlJP67DPXX9Ps4Cdz5V7Y34RVuh
[payer_email] => Xxxxx.XXXXXX######################
[mc_shipping1] => 0.00
[tax1] => 0.00
[txn_id] => 1KT33284H2515141A
[payment_type] => instant
[last_name] => XXXXXXX
[address_state] => Amberley
[item_name1] => Greenstone Toki [1734]
[receiver_email] => [email protected]
[payment_fee] =>
[quantity1] => 1
[receiver_id] => SWXD4VWFT5AB4
[txn_type] => cart
[mc_gross_1] => 160.00
[mc_currency] => NZD
[residence_country] => NZ
[receipt_id] => 2818-7805-8686-3347
[transaction_subject] =>
[payment_gross] =>
[ipn_track_id] => 21b7645ac8afb
)


Jun 05 2015 22:39 -- CURL OPTS: Array
(
[10002] => https://www.paypal.com/cgi-bin/webscr
[47] => 1
[10015] => cmd=_notify-validate&mc_gross=168.50&invoice=1412-1433500757-%5BXXXXXX%5D&protection_eligibility=Ineligible&address_status=unconfirmed&item_n umber1=4005&payer_id=UT3LNSAFG6QV6&tax=0.00&address_street=XX+XXXX+XXXX%0D%0ARD. +1&payment_date=03%3A39%3A21+Jun+05%2C+2015+PDT&payment_status=Completed&charset =windows-1252&address_zip=7481&mc_shipping=8.50&mc_handling=0.00&first_name=XXXXX&mc_fee= 6.18&address_country_code=NZ&address_name=XXXXXX+XXXXXX&notify_version=3.8&custo m=EC-1412-1433500757&payer_status=unverified&address_country=New+Zealand&num_cart_items=1& mc_handling1=0.00&address_city=Amberley&verify_sign=AOHgDv0QV7M8TthilveJDmE5eO6i ARlJP67DPXXXXXXXY34RVuh&payer_email=XXXX.XXXXX%40gmail.com&mc_shipping1=0.00&tax 1=0.00&txn_id=1KT33284H2515141A&payment_type=instant&last_name=XXXXXX&address_st ate=Amberley&item_name1=Greenstone+Toki+%5B1734%5D&receiver_email=XXXXXXXX%40XXX XX.com&payment_fee=&quantity1=1&receiver_id=SWXD4VWFT5AB4&txn_type=cart&mc_gross _1=160.00&mc_currency=NZD&residence_country=NZ&receipt_id=2818-7805-8686-3347&transaction_subject=&payment_gross=&ipn_track_id=21b7645ac8afb
[13] => 45
[78] => 30
[41] => 0
[42] => 0
[52] => 0
[19913] => 1
[75] => 1
[74] => 1
[84] => 2
[10018] => Zen Cart(R) - IPN Postback
)


Jun 05 2015 22:39 -- CURL response: VERIFIED

Jun 05 2015 22:39 -- IPN INFO (cl) - Confirmation/Validation response VERIFIED

Jun 05 2015 22:39 -- Breakpoint: 1 - Collected data from PayPal notification

Jun 05 2015 22:39 -- Breakpoint: 2 - Validated transaction components

Jun 05 2015 22:39 -- Breakpoint: 3 - Communication method verified

Jun 05 2015 22:39 -- IPN NOTICE :: Could not find matched txn_id record in DB. Therefore is new to us.

Jun 05 2015 22:39 -- Breakpoint: 4 - Details: txn_type=unique ordersID = 0 IPN_id=0

Relevant data from POST:
txn_type = unique
parent_txn_id = None
txn_id = 1KT33284H2515141A

Jun 05 2015 22:39 -- Breakpoint: 5 - Transaction type (txn_type) = cart [parentLookup=unique]

Jun 05 2015 22:39 -- Breakpoint: 5 - midstream checkpoint

Jun 05 2015 22:39 -- Breakpoint: 5 - Record does not need to be processed since it is not new and is not an update. See earlier notices. Processing aborted.