Transaction ran twice for single contribution

[cmmadmin]

CiviCRM 4.6.14, Drupal 7.43, iATS Payments extension 1.5.3

A donor made a one-time ACH donations on 10/29. He called and told us he had two charges on his bank statement. We researched this in civi and see only one donation on this date.

But, we found two transactions in iATS. We called iATS to ask why this transaction was ran twice. iATS told us they received two transaction triggers from Civi to run this transaction.

Is there anything we can do to determine why civi triggered this transaction to run twice, but only recorded one?

We found these 2 transactions at iatspayments.com: Reports > Journal > ACHEFT Approval Date = 10/29/2017 Select ACHEFT Approval

Invoice: b3b9b526eaf761e0f4a1c0fdaa278525 Transaction ID: AA29B8DE Date and Time: 10/29/2017 12:27:35 Name: Mxxx Hxxx

Invoice: 67297ff754ebc0ff3845f045c0b97513 Transaction ID: AA29B915 Date and Time: 10/29/2017 12:34:41 Name: Mxxx L. Hxxx

NOTE: The name on first transaction does not include the middle initial. Not sure if this is a clue.

In Civi, one Contribution appears for this donor on 10/31 with details: From Mxxx L. Hxxxx Financial Type xyz Total Amount $ 100.00 Fee Amount $ 0.00 Net Amount $ 100.00 Received October 29th, 2017 2:34 PM Received Into iATS CC Payment Processor Account Contribution Status Completed Paid By ACH/EFT (Credit) Source Online Contribution Page xyz Receipt Sent October 30th, 2017 10:00 AM Transaction ID AA29B915:1509375610 Invoice ID 67297ff754ebc0ff3845f045c0b97513

We verified b3b9b526eaf761e0f4a1c0fdaa278525 is not in the CiviCRM Contribution table as follows:

This query returned 1 record:

SELECT * FROM civicrm_contribution WHERE invoice_id LIKE '67297ff754ebc0ff3845f045c0b97513'

This query returned 0 records:

SELECT * FROM civicrm_contribution WHERE invoice_id LIKE 'b3b9b526eaf761e0f4a1c0fdaa278525'

Thank you for your help! -Malachi

[adixon]

The time of the multiple iATS contributions suggests that they actually submitted the request twice, but that the first one triggerred a repy that had them think it hadn't gone through. There were some recent outages on the iATS server that might account for something like this, or it could be some other failure in server-to-server communications. Did you check the civicrm_iats_request_og and response log?

The fact that they put their name in slightly differently each time strongly suggests this wasn't CiviCRM submitting the contribution twice of it's own accord, in any case.

[cmmadmin]

Thanks for the response. Can you tell me where I can find the civicrm_iats_request_og and response log?

[adixon]

Those are civicrm tables.

[cmmadmin]

I see 2 request records for the missing transaction and 1 for the one that is not missing. I see 2 response records for the missing transactions and 1 for the one that is not missing.

The requests seem similar. The auth_result and remote_id are NULL for the requests for the missing transaction.

Is this helpful?

This query returned 2 records (this is the missing invoice):

SELECT * 
FROM  `civicrm_iats_request_log` 
WHERE  `invoice_num` LIKE  'b3b9b526eaf761e0f4a1c0fdaa278525'

id: 2862 invoice_num: b3b9b526eaf761e0f4a1c0fdaa278525 ip: xxx.xxx.xxx.xxx cc: NULL customer_code: NULL total: 100.00 response_datetime: 2017-10-29 14:23:43

id: 2863 invoice_num: b3b9b526eaf761e0f4a1c0fdaa278525 ip: xxx.xxx.xxx.xxx cc: NULL customer_code: NULL total: 100.00 response_datetime: 2017-10-29 14:25:49

This query returned 2 records (this is the missing invoice):

SELECT * 
FROM  `civicrm_iats_response_log` 
WHERE  `invoice_num` LIKE  'b3b9b526eaf761e0f4a1c0fdaa278525'

id: 2765 invoice_num: b3b9b526eaf761e0f4a1c0fdaa278525 auth_result: NULL remote_id: NULL response_datetime: 2017-10-29 14:25:44

id: 2766 invoice_num: b3b9b526eaf761e0f4a1c0fdaa278525 auth_result: NULL remote_id: NULL response_datetime: 2017-10-29 14:27:49

This query returned 1 record (this is the invoice that is not missing in Civi):

SELECT * 
FROM  `civicrm_iats_request_log` 
WHERE  `invoice_num` LIKE  '67297ff754ebc0ff3845f045c0b97513'

id: 2865 invoice_num: 67297ff754ebc0ff3845f045c0b97513 ip: xxx.xxx.xxx.xxx cc: NULL customer_code: NULL total: 100.00 response_datetime: 2017-10-29 14:34:40

This query returned 1 record (this is the invoice that is not missing in Civi):

SELECT * 
FROM  `civicrm_iats_response_log` 
WHERE  `invoice_num` LIKE  '67297ff754ebc0ff3845f045c0b97513'

id: 2768 invoice_num: 67297ff754ebc0ff3845f045c0b97513 auth_result: OK: 555555 remote_id: AA29B915 response_datetime: 2017-10-29 14:27:49

[cmmadmin]

I guess this log data brings up these questions:

1. If there was an outage on the iATS server would the _civicrm_iats_responselog report an entry with auth_result: NULL and remote_id: NULL? Is that what we would expect to see?
2. Why are there two requests 2 minutes apart recorded in the _civicrm_iats_requestlog for the missing invoice, with same invoice number (b3b9b526eaf761e0f4a1c0fdaa278525)? What would cause this?

[adixon]

Great questions, and for sure debugging issues like this deserves a wiki page.

Your logs suggest that your server twice tried to process the ("failed", missing from civi) payment and failed to get a coherent response, i.e. the iATS server responded both times with an invalid response, or at least one that the iATS plugin failed to parse properly. The fact that your server made the same request twice suggests that the initial request returned some kind of failed error code to the user and then they (appropriately) tried again and also failed. And then they tried again from the beginning, and were successful.

Most importantly: I notice that the timing of your transactions corresponds to this advisory you should have received: "Please be advised that due to a system error, some of our mutual clients' credit card transactions, processed on Sunday, October 29th 2017 between approximately 7:30am PST – 2:15pm PST, may have resulted in a reject Timeout."

Although your symptom doesn't exactly match, my best guess is that this is related and the cause, and you could confirm by checking with iATS.

[IowaBoy1]

We have been having this same issue since Aug. Ours are all recurring ACH contributions that have been happily processing without a hitch. The first time it happened, there was an iATS outage and we assumed that impacted it. But now it has happened 3xs since. Once a month with 4 different donors.

The common denominator in ours seems to be that it is always the last recurring ACH to process on the 1st of the month. That one then processes again on the 2nd. Both transactions are shown in our iATS reports, but only the one on the 2nd shows in Civi.

The civicrm_iats_journal, civicrm_iats_request, and civicrm_iats_response all show both transactions. iats_verify and civicrm_contribution only show the one that processed on the 2nd.

[adixon]

That's a fascinating symptom, although I think fundamentally different from this issue, I'd recommend you post it separately.

Specifically - your experience is related to the automated recurring job, vs. this issue which was a user-triggered contribution.

But also, it's an excellent example of the need for the new and improved verification scheme - the next release should have a feature that will get iATS reports and allow Civi to recover from some unexpected failures.

Your example is quite baffling - there's nothing magic about the last recurring contribution as far as I can tell that could cause it to fail like that. In general, any kind of failure should leave behind a trail of some kind. Do check your logs of course.

[IowaBoy1]

"Check your logs."
do you mean the civicrm_iats_journal, civicrm_iats_request, and civicrm_iats_response?? Or is there somewhere else to look?

[adixon]

I meant the civicrm error log, usually in files/civicrm/ConfigAndLog/

What your symptom tells me is that everything went well until the moment with the last contribution, which had been created in pending, then transacted with iats, and should have been marked as complete. Instead it was deleted (or potentially, it was deleted by a different process later on, but that seems even weirder). I'd also look into the numbering of the civicrm contributions and see if there's a gap in there.

[IowaBoy1]

I posted a new issue here https://github.com/iATSPayments/com.iatspayments.civicrm/issues/228