Unknown Exception related caused database to roll back trigging same payment multiple days

[seamuslee001]

A client of ours had a rather terrible issue occur where by there seemed to be some kind of uncaught Exception likely because of the usage of the Sparkpost email extension or similar. This some how in turned caused a database roll of a contribution and recurring contribution record updates. There was no record of the recurring contributions iats job finishing in the scheduled jobs log either.

What this meant was that the same recurring payment was tried every single day for like a week or more which was incredibly embarrassing for the client.

We haven't yet figured out where this might have fallen over but we suspect it was one of these 2 API calls https://github.com/iATSPayments/com.iatspayments.civicrm/blob/f9783a6466c9c8adc05cf7f9ee454fca6a44cb6e/CRM/Iats/Transaction.php#L144 or perhaps in https://github.com/iATSPayments/com.iatspayments.civicrm/blob/f9783a6466c9c8adc05cf7f9ee454fca6a44cb6e/CRM/Iats/Transaction.php#L156, it is also possible it came from the repeattransaction call but that seems unusual

cc @monishdeb @Edzelopez

[KarinG]

Yikes… next scheduled contribution date plays an important role in the processing of recurring contributions. If that date is stuck in the past it can result in consecutive payments. Ping me on Mattermost @seamuslee001 if you’d like to connect on this via GoTo.

[adixon]

Yeah, I've seen all kinds of failures underneath completetransaction, often related to a mail failure.

It's wrapped in a try/catch but even with that, the mail-related failures can be show stoppers.

Some time ago, we updated the flow so that the code advances the next scheduled date before trying to take the money (i.e. an attempt to never have this happen), so I'm curious what circumstances is generating this scenario still, unless you're on some old or branched code copy?

[seamuslee001]

So the large problem we have at the moment is we have no logs, no nothing, that proves exactly what happened here but we know that it got to at least here https://github.com/iATSPayments/com.iatspayments.civicrm/blob/master/CRM/Iats/Transaction.php#L88 because the payment was successful in Iats system and logged there and in the journal

What we don't have is knowledge of where it failed, because no contribution record was created or anything like that it is I suppose possible the repeat transaction failed in some strange way and some how possibly caused a database rollback of some kind if all of this was done in a MySQL transaction.

The client we are working with is on Drupal 7, CiviCRM 5.43.0, and Iats is 1.7.4

[adixon]

Ah, but there are more clues! Take a look in civicrm_iats_request_log and civicrm_iats_response_log.

This smells familiar from the past year and I think you'll find some useful clues in those tables.

Ah yes, I recall! The issue was a recurring contribution that was setup and left in a pending or failed state, I can't remember which. The original pending contribution got created when the client credentials were wrong, or something like that.

But the request/response log will show you the contact id that this is happening for, and I'll bet you'll find a weird/broken recurring contribution schedule attached.

[Edzelopez]

Hey @adixon, I've been working with @seamuslee001 on this. I've taken alook at the iATS request and response log tables and can confirm the invoice IDs match the one's from iATS, which tell me that CiviCRM did process the payments. I can also confirm that the associated contribution records are nowhere to be found in CiviCRM, which means they were rolled back. I do not however see a link to a recurring contribution schedule, as the request and response tables do not have FKs to either.

I think the large part of what we are trying to ensure here is once payment is collected, we never rollback a transaction. cc @JoeMurray

Do you have any thoughts on how this can be done? Updating the recurring schedule ahead of time seems like the way to move forward, with a check being done after the payment is processed, so we can roll back the date if there is a failure.

[adixon]

The first thing is to understand how this specific case happened and prevent it recurring in your specific case(s)!

Did you find the recurring contribution that was triggering it as I suggested? Any clues?

Then we can have a better idea of how to remedy it.

FWIW - the suggestion you make is already implemented (some time ago), the problem is something slightly more obscure I believe.

[JoeMurray]

The client paid up their Mail processor, so mailing of receipt works, so we aren't seeing this continue. We do know the transaction was related to membership payment. I am not sure if it was a single post-dated future transaction or a recurring. There were two people affected. As the immediate issue is resolved, and we have little additional information, this has slipped in priority. My sense mentioned previously is that the proper architectural approach needs to be move the mailing action to after the database transaction boundary for committing the payment. Once the payment processor has given a success response, that has to be logged into CiviCRM's database and can't be dependent on something like successfully sending the receipt to the contributor.

[adixon]

I believe your analysis and proposed solution are correct. As I understand it your suggested solution applies to CiviCRM core, correct? I'll leave this open bit longer in case anyone has suggestions for better error handling by this extension, but will assume you're posting the issue to CiviCRM core (I believe it would be for the completetransaction and/or repeattransaction api calls).