Posted by mattreba on October 5, 2012 at 12:39am
3 followers
Jump to:
| Project: | Commerce PayPal |
| Version: | 7.x-1.x-dev |
| Component: | PayPal WPS |
| Category: | support request |
| Priority: | normal |
| Assigned: | Unassigned |
| Status: | postponed (maintainer needs more info) |
Issue Summary
In the past couple of months I've had an issue pop up randomly on some PayPal transactions where the payment shows twice in the admin views with time stamps (created/changed) just a few seconds apart but otherwise identical. I've verified with PayPal that only a single payment was captured. This does not involve foreign currencies as was mentioned in another issue. I havenever had this occur with Auth.net transactions which are also enabled on my site. Is it possible that some users click back or refresh causing two successful transaction messages to be captured?
Here are the rows from the payment table for an example order. I apologize if I took too much detail out but i didn't want to risk exposing customer data:
(196, 196, 0, 623, 'paypal_wps', 'paypal_wps|commerce_payment_paypal_wps', '04K341671P088693R', 'The payment has completed.', 'a:0:{}', 24318, 'USD', 'success', 'Completed', '
a : 1 : {
i : 1349393043;
a : 50 : {
s : 8 : "mc_gross";
s : 6 : "243.18";
s : 7 : "invoice";
s : 14 : "623-1349392965";
s : 9 : "item_mpn1";
s : 0 : "";
s : 22 : "protection_eligibility";
s : 10 : "Ineligible";
s : 16 : "item_count_unit1";
s : 1 : "0";
s : 12 : "item_number1";
s : 0 : "";
s : 3 : "tax";
s : 4 : "0.00";
s : 8 : "payer_id";
s : 13 : "Sanitized";
s : 12 : "payment_date";
s : 25 : "16:19:05 Oct 04, 2012 PDT";
s : 14 : "item_tax_rate1";
s : 1 : "0";
s : 19 : "option_selection1_1";
s : 1 : "1";
s : 14 : "payment_status";
s : 9 : "Completed";
s : 7 : "charset";
s : 12 : "windows-1252";
s : 11 : "mc_shipping";
s : 4 : "0.00";
s : 21 : "item_tax_rate_double1";
s : 4 : "0.00";
s : 11 : "mc_handling";
s : 4 : "0.00";
s : 10 : "first_name";
s : 5 : "Sanitized";
s : 6 : "Sanitized";
s : 4 : "7.35";
s : 14 : "notify_version";
s : 3 : "3.7";
s : 6 : "custom";
s : 0 : "";
s : 12 : "payer_status";
s : 10 : "unverified";
s : 8 : "business";
s : 23 : "Sanitized";
s : 14 : "num_cart_items";
s : 1 : "1";
s : 12 : "mc_handling1";
s : 4 : "0.00";
s : 11 : "verify_sign";
s : 56 : "Sanitized";
s : 11 : "payer_email";
s : 18 : "Sanitized";
s : 12 : "mc_shipping1";
s : 4 : "0.00";
s : 18 : "item_style_number1";
s : 0 : "";
s : 4 : "tax1";
s : 4 : "0.00";
s : 14 : "option_name1_1";
s : 13 : "Product count";
s : 9 : "item_plu1";
s : 0 : "";
s : 6 : "txn_id";
s : 17 : "Sanitized But Matches Dupe";
s : 12 : "payment_type";
s : 7 : "instant";
s : 9 : "last_name";
s : 6 : "Sanitized";
s : 10 : "item_isbn1";
s : 0 : "";
s : 10 : "item_name1";
s : 46 : "Sanitized";
s : 14 : "receiver_email";
s : 23 : "Sanitized";
s : 11 : "payment_fee";
s : 4 : "7.35";
s : 9 : "quantity1";
s : 1 : "1";
s : 11 : "receiver_id";
s : 13 : "Sanitized";
s : 8 : "txn_type";
s : 4 : "cart";
s : 18 : "item_model_number1";
s : 0 : "";
s : 10 : "mc_gross_1";
s : 6 : "243.18";
s : 11 : "mc_currency";
s : 3 : "USD";
s : 13 : "item_taxable1";
s : 1 : "N";
s : 17 : "residence_country";
s : 2 : "US";
s : 19 : "transaction_subject";
s : 59 : "Sanitized";
s : 13 : "payment_gross";
s : 6 : "243.18";
s : 12 : "ipn_track_id";
s : 13 : "Sanitized but matched";
s : 8 : "order_id";
s : 3 : "623";
}
}
', 1349393043, 1349393043, NULL),
(197, 197, 0, 623, 'paypal_wps', 'paypal_wps|commerce_payment_paypal_wps', '04K341671P088693R', 'The payment has completed.', 'a:0:{}', 24318, 'USD', 'success', 'Completed', '
a : 1 : {
i : 1349393058;
a : 50 : {
s : 8 : "mc_gross";
s : 6 : "243.18";
s : 7 : "invoice";
s : 14 : "623-1349392965";
s : 9 : "item_mpn1";
s : 0 : "";
s : 22 : "protection_eligibility";
s : 10 : "Ineligible";
s : 16 : "item_count_unit1";
s : 1 : "0";
s : 12 : "item_number1";
s : 0 : "";
s : 3 : "tax";
s : 4 : "0.00";
s : 8 : "payer_id";
s : 13 : "Sanitized";
s : 12 : "payment_date";
s : 25 : "16:19:05 Oct 04, 2012 PDT";
s : 14 : "item_tax_rate1";
s : 1 : "0";
s : 19 : "option_selection1_1";
s : 1 : "1";
s : 14 : "payment_status";
s : 9 : "Completed";
s : 7 : "charset";
s : 12 : "windows-1252";
s : 11 : "mc_shipping";
s : 4 : "0.00";
s : 21 : "item_tax_rate_double1";
s : 4 : "0.00";
s : 11 : "mc_handling";
s : 4 : "0.00";
s : 10 : "first_name";
s : 5 : "Sanitized";
s : 6 : "Sanitized";
s : 4 : "7.35";
s : 14 : "notify_version";
s : 3 : "3.7";
s : 6 : "custom";
s : 0 : "";
s : 12 : "payer_status";
s : 10 : "unverified";
s : 8 : "business";
s : 23 : "Sanitized";
s : 14 : "num_cart_items";
s : 1 : "1";
s : 12 : "mc_handling1";
s : 4 : "0.00";
s : 11 : "verify_sign";
s : 56 : "Sanitized";
s : 11 : "payer_email";
s : 18 : "Sanitized";
s : 12 : "mc_shipping1";
s : 4 : "0.00";
s : 18 : "item_style_number1";
s : 0 : "";
s : 4 : "tax1";
s : 4 : "0.00";
s : 14 : "option_name1_1";
s : 13 : "Product count";
s : 9 : "item_plu1";
s : 0 : "";
s : 6 : "txn_id";
s : 17 : "Sanitized But Matches Dupe";
s : 12 : "payment_type";
s : 7 : "instant";
s : 9 : "last_name";
s : 6 : "Sanitized";
s : 10 : "item_isbn1";
s : 0 : "";
s : 10 : "item_name1";
s : 46 : "Sanitized";
s : 14 : "receiver_email";
s : 23 : "Sanitized";
s : 11 : "payment_fee";
s : 4 : "7.35";
s : 9 : "quantity1";
s : 1 : "1";
s : 11 : "receiver_id";
s : 13 : "Sanitized";
s : 8 : "txn_type";
s : 4 : "cart";
s : 18 : "item_model_number1";
s : 0 : "";
s : 10 : "mc_gross_1";
s : 6 : "243.18";
s : 11 : "mc_currency";
s : 3 : "USD";
s : 13 : "item_taxable1";
s : 1 : "N";
s : 17 : "residence_country";
s : 2 : "US";
s : 19 : "transaction_subject";
s : 59 : "Sanitized";
s : 13 : "payment_gross";
s : 6 : "243.18";
s : 12 : "ipn_track_id";
s : 13 : "Sanitized but matched";
s : 8 : "order_id";
s : 3 : "623";
}
}
', 1349393058, 1349393058, NULL);
Comments
#1
Honestly, I'm not sure how this can happen. Part of our IPN validation prior to actually creating any payment transaction is to ensure the IPN hasn't already been processed. The pertinent code is in commerce_paypal.module:
<?php// Exit if the IPN has already been processed.
if (!empty($ipn['txn_id']) && $prior_ipn = commerce_paypal_ipn_load($ipn['txn_id'])) {
if ($prior_ipn['payment_status'] == $ipn['payment_status']) {
watchdog('commerce_paypal', 'Attempted to process an IPN that has already been processed with transaction ID @txn_id.', array('@txn_id' => $ipn['txn_id']), WATCHDOG_NOTICE);
return FALSE;
}
}
?>
Do you see that message in your log anywhere? Looking at the timestamps in your payment transaction data arrays, I can see that these transactions are being create a mere 15 seconds apart. The challenge will be to determine why - what can result in this happening without the above check not catching the problem?
Do you have any custom code running on this site at all? Anything else you can glean from the logs? Why not turn on IPN logging and look at how the IPN array is structured. Does it actually have a txn_id specified each time?
#2
Unfortunately this has not occurred since.
IPN logging is enabled. The txn_id of each payment is a match. Unfortunately by the time I discovered this payment my watchdog log had already rolled over so I cannot report on other log messages around the time of this occurring.
I have many contrib modules installed but nothing related to payments except the Authorize.net module. No custom modules.
I have one sandbox module (Commerce Quickbooks Webconnect) in use. It does implement hook_commerce_payment_transaction_insert/delete/update but it appears benign to me. http://drupalcode.org/sandbox/stephen.colson/1100862.git/blob/HEAD:/commerce_qb_webconnect.module#l440
I expect it is unrelated but I was also surprised to see PayPal refunds showing up in the payments tab. Refunds were executed on the PayPal website and not through any Commerce modules. Can you confirm this is expected behavior?
#3
Also getting double entries. System loggin says this. It validates the order twice:
__________
commerce_paypal_wps 05.02.2013 - 21:21 IPN processed for Order 4353 with ID (.......). Guest (not confirmed)
commerce_paypal_wps 05.02.2013 - 21:21 IPN validated for Order 4353 with ID (.....). Guest (not confirmed)
Rules 05.02.2013 - 21:21 Unable to evaluate condition entity_has_field. Guest (not confirmed) edit configuration
Rules 05.02.2013 - 21:21 The variable or parameter entity is empty. Guest (not confirmed)
variable_email 05.02.2013 - 21:21 Successfully sent email to office@.......com Guest (not confirmed)
Rules 05.02.2013 - 21:21 Successfully sent email to office@......com Guest (not confirmed)
commerce_paypal_wps 05.02.2013 - 21:21 IPN validated for Order 4353 with ID (.....).
__________