Duplicate recurring contributions - "Failure, Error message: Expected one Contribution but found 0"

CiviCRM 5.3.1 iATSPayments 1.6.2 Drupal 7.59

We have discovered that 59 recurring contributions were processed twice. They were processed on 09/04/2018 and then again on 09/05/2018. Is this an issue in the payment processor or with iATS?

NOTE: All recurring contributions have run correctly since then (09/06 to 09/10).

On the first day, 09/04/2018, these 59 contributions were processed by iATS but we do not have a record that they ran in CiviCRM except the Schedule Jobs log shows the error "Failure, Error message: Expected one Contribution but found 0" as show below:

2018-09-04 02:30:02
Entity: Job Action: iatsrecurringcontributions
Summary
Starting execution of iATS Payments Recurring Contributions
Details

Parameters raw (From cron.php): 
a:1:{s:7:"version";i:3;}

Parameters parsed (and passed to API method): 
a:1:{s:7:"version";i:3;}

Full message: 
Starting execution of iATS Payments Recurring Contributions

2018-09-04 02:31:26
Entity: Job Action: iatsrecurringcontributions
Summary
Finished execution of iATS Payments Recurring Contributions with result: Failure, Error message: Expected one Contribution but found 0
Details

Parameters raw (From cron.php): 
a:1:{s:7:"version";i:3;}

Parameters parsed (and passed to API method): 
a:1:{s:7:"version";i:3;}

Full message: 
Finished execution of iATS Payments Recurring Contributions with result: Failure, Error message: Expected one Contribution but found 0

On the second day, 09/05/2018, there were 277 recurring contributions processed, including the 59 contributions that ran the previous day. Schedule Jobs log looked normals as follows:

2018-09-05 02:30:02
Entity: Job Action: iatsrecurringcontributions
Summary
Starting execution of iATS Payments Recurring Contributions
Details

Parameters raw (From cron.php): 
a:1:{s:7:"version";i:3;}

Parameters parsed (and passed to API method): 
a:1:{s:7:"version";i:3;}

Full message: 
Starting execution of iATS Payments Recurring Contributions

2018-09-05 02:36:00
Entity: Job Action: iatsrecurringcontributions
Summary
Finished execution of iATS Payments Recurring Contributions with result: Success (277 contribution record(s) were processed.
Successfully processed pending recurring contribution in series id 5154: OK: 555555
Created activity (...)
Details

Parameters raw (From cron.php): 
a:1:{s:7:"version";i:3;}

Parameters parsed (and passed to API method): 
a:1:{s:7:"version";i:3;}

Full message: 
Finished execution of iATS Payments Recurring Contributions with result: Success (277 contribution record(s) were processed.
Successfully processed pending recurring contribution in series id 5154: OK: 555555
Created activity record for contact id 126991
...

The duplicates were due to an incomplete processing on the first of the duplicates. The message "Expected one Contribution but found 0" is likely from the followup processing that the iats extension does after recording a contribution. If the issue hasn't recurred, the it's likely some transient server-related issue of the day.

@adixon This issue has happened to us again on 1/7/2019. We had 46 transactions that were duplicated (processed twice by iATS). All of these transactions were scheduled to run on 1/7 in Civi, however, when the Chron job ran it gave Error message: "Expected one Contribution but found 0". These transactions were included in the Chron job again on 1/8 and were processed in iATS again. Payments for these transactions were processed twice by iATS. This also happened to us on Sep 11 as noted above. This is a serious issue because have to reach out to our donors and apologize for charging them twice.

Can something be implemented to ensure there is a fail-safe handshake that ensures this type of duplication processing will not occur?

Error details from schedule job and Civi log are below.

We would really appreciate a solution to this issue. -Malachi

At 2019-01-07 02:31:30 the iATS Payments Recurring Contributions scheduled job finished with this error:

"Finished execution of iATS Payments Recurring Contributions with result: Failure, Error message: Expected one Contribution but found 0"

Civi Log shows these errors:

Jan 07 02:30:03 [info] $Fatal Error Details = Array ( [callback] => Array ( [0] => CRM_Core_Error [1] => exceptionHandler )

[code] => -1
[message] => DB Error: unknown error
[mode] => 16
[debug_info] => 
    DELETE gc
    FROM civicrm_group_contact_cache gc
    INNER JOIN civicrm_group g ON g.id = gc.group_id
    WHERE g.cache_date <= '20190107023003'
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[type] => DB_Error
[user_info] => 
    DELETE gc
    FROM civicrm_group_contact_cache gc
    INNER JOIN civicrm_group g ON g.id = gc.group_id
    WHERE g.cache_date <= '20190107023003'
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="
    DELETE gc
    FROM civicrm_group_contact_cache gc
    INNER JOIN civicrm_group g ON g.id = gc.group_id
    WHERE g.cache_date <= '20190107023003'
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]

)

...

Jan 07 02:30:03 [info] Retrying after Database deadlock encountered hit on attempt 1 at query : DELETE gc FROM civicrm_group_contact_cache gc INNER JOIN civicrm_group g ON g.id = gc.group_id WHERE g.cache_date <= '20190107023003'

Jan 07 02:30:03 [info] $Fatal Error Details = Array ( [callback] => Array ( [0] => CRM_Core_Error [1] => exceptionHandler )

[code] => -1
[message] => DB Error: unknown error
[mode] => 16
[debug_info] => INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[type] => DB_Error
[user_info] => INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]

)

...

Jan 07 02:30:03 [info] Retrying after Database deadlock encountered hit on attempt 1 at query : INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id) SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192

Jan 07 02:30:04 [info] Contribution record updated successfully

Jan 07 02:30:04 [info] Success: Database updated

...

Jan 07 02:30:54 [info] $Fatal Error Details = Array ( [callback] => Array ( [0] => CRM_Core_Error [1] => exceptionHandler )

[code] => -1
[message] => DB Error: unknown error
[mode] => 16
[debug_info] => INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1205 ** Lock wait timeout exceeded; try restarting transaction]
[type] => DB_Error
[user_info] => INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1205 ** Lock wait timeout exceeded; try restarting transaction]
[to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
    SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192
   [nativecode=1205 ** Lock wait timeout exceeded; try restarting transaction]"]

)

...

Jan 07 02:30:54 [info] Retrying after Database lock encountered hit on attempt 2 at query : INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id) SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache192

Jan 07 02:30:54 [info] Contribution record updated successfully

Jan 07 02:30:54 [info] Success: Database updated

Yes, we've started work on a restructure of the code so that the next-scheduled-contribution-date is pushed forward before the payment is taken, and then pulled back in case of confirmed failure. You'll still want to monitor your install for issues like the above, but it'll err more on the side of caution.

For your case - sounds like you've got too many large smart groups? You might change the calculation of smart groups from "on demand" to something else, I suspect you've got a smart group that depends on contributions and that smart group is getting triggered for recalculation during the recurring payment job.

Thanks @adixon I changed 'Run frequency' for the 'Rebuild Smart Group Cache' scheduled job from 'Every time cron job is run' to 'Daily'. Is this what you're referring to? Our scheduled jobs cron runs every 15 minutes, so it's likely that job ran at the same time as the 'iATS Payments Recurring Contributions' job.

@adixon It's good to hear you are working on a fix. I suspect the seriousness of this situation warrants an additional handshake to fail-safe the process. Would something such as the following be feasible?

Civi pushes next-scheduled-contribution-date forward.
Civi sends payment request to iATS.
iATS processes payment.
iATS sends payment status to Civi (Success, Fail, etc).
Civi receives payment status. If Fail, next-scheduled-contribution-date is reverted.
If Civi does not receive payment status (after a fixed timeout period) then it requests the payment status again from iATS. Repeat this step until a payment status is received.

I suspect that step 6 is what is not being done, which leads to issues when there is a failure or lost message. If the next-scheduled-contribution-date push is simply moved ahead in the process without something like step 6, then we may end up with skipped recurring contributions, correct?

Also, whenever an error occurs could an email be sent to our financial admin to notify them that something failed?

Perhaps there is a more elegant solution. Just brainstorming how we can make this process more reliable which is important to us.

Thank you for bringing this to our attention. We are prioritizing addressing the workflow to prevent this from happening in future.

Yes, you have nicely described the new flow plan. The previous flow only pushed the next scheduled date forward after getting an answer from iATS, so if iATS processed the payment but that information didn't get back to Civi for whatever reason, then the next job run would re-charge the same card again.

Fortunately, Civi is already checking iATS for completed ACH/EFT payments, so extending this to check for completed cc payments when CiviCRM has been left hanging should be relatively straightforward.

An email with errors sounds like a worthwhile feature as well.

We have been in contact with iATS about this issue. They have indicated it has been escalated to their Senior Support Team. Has any progress been made on the CiviCRM side? Perhaps you could coordinate with them to implement the fix?

I have provided iATS with an excerpt of the CiviCRM log files during the time the issue occurred and directed them to the issue description on this page.

We have added edits in the code base to change the handling of next scheduled date workflow - and are in the process of running our test matrix prior to releasing it.

Hi there, is this change in master now? I'm guessing that's from March 25? - https://github.com/iATSPayments/com.iatspayments.civicrm/commit/cf4de1ebcfdd38cf6dfba7825f0e3350ff3c42db

We're having a similar issue, but might not be quite the same. Will try updating to the latest code as part of fixing it.

We're getting duplicates of all recurring contributions, which shows up in the journal in iATS, but no record of this in Civi. Not seeing anything about the 2nd payment at all in the contribution info, Civi "iats payments admin" page, Civi log, or scheduled jobs log.

In the iATS journal, the correct payment shows up at a given time (when the Civi cron job ran), and the duplicate payment shows up about 45 mins later.

This used to be working, then we migrated the site to a different server and ran the drupal/civi software updates. The other issue we've had since then has been problems with outgoing email. So the most likely scenario might be that the payment is trying to send an outgoing email which maybe fails and then the payment is attempted a second time. I'm not sure if that makes sense?

Hi Martin:

I'll guess that your duplicates are recurring contributions still being generated by your old server/site?

The mail issue is usually just one of optics for the donor (i.e. they think their donation hasn't gone through but it has), but the Civi-Iats admin page and the iATS server have no disagreement about what's going on.

The old site, of course... sigh >_< Thanks for the help :)

We are experiencing the same issue as the OP for one of our clients. Glad to see that this issue is known and being addressed. Is there any sense of an ETA yet of the related PRs being tagged for release?

@adixon @KarinG This appears to be happening again at an increasing rate.

On April 21, April 23 and May 2 several ACH donations and credit card donations were duplicated in iATS. These recurring donations were scheduled to run on April 21, April 23 and May 2 respectively. They did run in iATS, but did not run in Civi and are not listed in the scheduled jobs log. Since the donations did not show as completed in Civi they ran again the following night in both iATS and Civi. Our team had to manually input the donations from the first night into Civi and reach out to each donor with the issue.

We upgraded the iATS extension to 1.7.4 a couple of months ago.

The 'Rebuild Smart Group Cache' scheduled job was set to run Weekly and last ran on April 29. I went agahed disabled it today just to be safe. Doesn't seem like this should apply though(?)

Is there any way we can prevent this? Please let me know if I can provide more information.

I found this error in the CiviCRM Log (not sure if it is related to this issue):

May 02 02:37:08 [error] $Fatal Error Details = Array
(
[callback] => Array
(
[0] => CRM_Core_Error
[1] => exceptionHandler
)

[code] => -3
[message] => DB Error: constraint violation
[mode] => 16
[debug_info] => INSERT INTO `civicrm_entity_financial_trxn` (`entity_table` , `entity_id` , `financial_trxn_id` , `amount` ) VALUES ('civicrm_financial_item' , 210516 , 313768 , 50.00 ) [nativecode=1452 ** Cannot add or update a child row: a foreign key constraint fails (`secure_civi`.`civicrm_entity_financial_trxn`, CONSTRAINT `FK_civicrm_entity_financial_trxn_financial_trxn_id` FOREIGN KEY (`financial_trxn_id`) REFERENCES `civicrm_financial_trxn` (`id`) ON D)]
[type] => DB_Error
[user_info] => INSERT INTO `civicrm_entity_financial_trxn` (`entity_table` , `entity_id` , `financial_trxn_id` , `amount` ) VALUES ('civicrm_financial_item' , 210516 , 313768 , 50.00 ) [nativecode=1452 ** Cannot add or update a child row: a foreign key constraint fails (`secure_civi`.`civicrm_entity_financial_trxn`, CONSTRAINT `FK_civicrm_entity_financial_trxn_financial_trxn_id` FOREIGN KEY (`financial_trxn_id`) REFERENCES `civicrm_financial_trxn` (`id`) ON D)]
[to_string] => [db_error: message="DB Error: constraint violation" code=-3 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="INSERT INTO `civicrm_entity_financial_trxn` (`entity_table` , `entity_id` , `financial_trxn_id` , `amount` ) VALUES ('civicrm_financial_item' , 210516 , 313768 , 50.00 ) [nativecode=1452 ** Cannot add or update a child row: a foreign key constraint fails (`secure_civi`.`civicrm_entity_financial_trxn`, CONSTRAINT `FK_civicrm_entity_financial_trxn_financial_trxn_id` FOREIGN KEY (`financial_trxn_id`) REFERENCES `civicrm_financial_trxn` (`id`) ON D)]"]
)

Fascinating, but first off I'd recommend you start a new issue.

In this case, that constraint violation error sounds like it could be the root of the problem. Specifically, the recurring payment job will try and create a (pending) contribution, then it'll try and take the money, and then it'll complete the contribution. If there are internal civicrm errors in the creation or completion of the contribution, there's going to be trouble. If you can get a backtrace and see at what point this error is happening, we'd probably get a better clue. It looks like it's happening at the contribution completion stage, and the foreign key constraint failure suggests that the real issue came immediately before this one.

Thanks for the response. Here's more context from the Civi log. Does this help?

Ah yes - so the error happens within the call to the repeattransaction api.

I've seen that there have been some updates to the ipn code in the last few civi versions, I suspect that's where this is coming from.

https://lab.civicrm.org/dev/core/-/issues?scope=all&utf8=%E2%9C%93&state=closed&search=ipn

In terms of how to fix it, I suspect there are some kind of edge-case type things at work here, since it's not failing for all of your contributions. If you can look at the ones that are failing and see any patterns, that might help.

Specifically, I'd look for the associated price sets for the failing recurring contributions and see if there are weirdnesses that might be cleaned up.

@adixon We don't see any differences with the contributions that are failing so far, but we'll keep looking.

Also, I forgot to include our version info: CiviCRM 5.24.5 Drupal 7.69 iATS 1.7.4

@adixon Thank you for looking into this. As you can expect this is an important issue for us to get resolved. We are happy to provide whatever information and assistance we can.

We have many contribution pages as we create one for each staff member that raises support. Each contribution page is setup exactly the same and we haven't found any differences with the ones that failed.

We do not use Price Sets but simply set them up with Financial Types and Financial Accounts as shown in the attached screenshots.

Is there anything we can inspect in the database tables that would be helpful?

Or, are these some log messages that we could add to our CiviCRM code that would be helpful to troubleshoot this issue if it occurs again? If so, if you can provide the code changes I can apply them to our installation.

We do have a large number of financial types and we do use the Summary Fields extension which has a scheduled job which is set to run monthly. I just mention that in case these could be culprits. The execution of the Summary Fields scheduled job do not correspond with the timing of these recurring contribution failures so doesn't seem to make sense that is doing it but perhaps it is leaving behind some residual effects?

Please let us know if there is anything we can do to help get this resolved. Thank you.

Screenshot 2021-05-07 042653 Screenshot 2021-05-07 042855 Screenshot 2021-05-07 042456 Screenshot 2021-05-07 042519

Reviewing the output -> I do see references to price sets -> price_field_id as well as price_field_value_id -> Could it be that the original series for this contact id [171955] was created with a price set [dating back to before you stopped using them?] and perhaps this field no longer exists?

                                                [price_field_id] => 458
                                                [qty] => 1.00
                                                [line_total] => 20.00
                                                [unit_price] => 20.00
                                                [label] => Other Amount
                                                [price_field_value_id] => 697
                                                [financial_type_id] => 498

@KarinG - I believe that even when you don't "use" price sets explicitly, when you input the allowed amounts for a contribution page, it implements that as a 'hidden' priceset.

@adixon @KarinG

CiviCRM 5.24.5 Drupal 7.69 Recurring Active Donors Custom Search (com.backofficethinking.activedonorssearch) version 1.0 iATS Payments (com.iatspayments.civicrm) version 1.7.4 Summary Fields (net.ourpowerbase.sumfields) version 4.0.2 FlexMailer (org.civicrm.flexmailer) version 1.1.1 CiviDiscount (org.civicrm.module.cividiscount) version 3.8.1 CiviCRM Bootstrap theme (org.civicrm.shoreditch) version 0.1.0-alpha.36 Sequential credit notes (sequentialcreditnotes) version 1.0 Mosaico (uk.co.vedaconsulting.mosaico) version 2.5.1597918155

This issue has occurred again. Several recurring contributions ran two days in a row (May 19 and May 20).

Error in Civi log is: [message] => DB Error: database lock timeout

Excerpt from Civi log is below.

The SumFields extension has a scheduled job that I previously set to run Quarterly. I noticed today this scheduled job had reset itself to run Hourly. Could this be the culprit? We have a long list of financial types that are are configured to used with the SumFields calculations.

Thanks for posting this. We've improved the error handling in the past few years, but you've found another way to break it!

For sure, the Database lock is the key error here, and your hypothesis about the sumfields extension seems reasonable.

@adixon @KarinG I have completely disabled the Summary Fields extension.

To prevent this from ever occurring is it possible to mark a recurring contribution as 'In Progress' or 'Pending' or something so that it will not repeat the next day if no response is received from iATS (due to a db lock or some other catastrophic server issue)?

@cmmadmin - that's exactly what the code is trying to do in the example you gave: contribution_status_id = 2 (Pending) and this fails as the tables are locked (presumably by summary fields extension).

To only run Summary Fields quarterly -> you can disable the Job and hit Execute now on it (Manually) 4x per year. Then you never risk that it will reset to its defaults (which sounds like it's hourly) and start producing conflicts with other Jobs (like the recurring contribution processing).

May 19 02:37:53  [info] Retrying after Database lock encountered hit on attempt 1 at query : INSERT INTO `civicrm_contribution` (`contact_id` , `financial_type_id` , `payment_instrument_id` , `receive_date` , `total_amount` , `fee_amount` , `net_amount` , `currency` , `source` , `contribution_recur_id` , `is_test` , `contribution_status_id` , `check_number` , `campaign_id` ) VALUES ( 116272 ,  47 ,  2 ,  20210519023702 ,  100.00 ,  0 ,  100 , 'USD' , 'iATS Payments (iATSServiceACHEFT) Recurring Contribution ( id = 5146 )' ,  5146 ,  0 ,  2 ,  NULL ,  11 )

@KarinG Thanks for your response. That makes sense.

At what point in the process does the IATS extension attempt to set the contribution_status_id to 2 (Pending)?

Perhaps, it should attempt to do this prior to sending the request to IATS and if it fails then do not proceed to send the command to IATs. Seems like this would prevent the contribution from being processed twice wouldn't it?

-Malachi

At a minimum would it be possible to add a feature to notify us by email when recurring contributions fail for any reason. We would want the email to include a list of the contributions that failed.

The problem is that the recurring contribution actually does not fail - it succeeds (money is captured) but when the code is trying to create the contribution record for it on your CiviCRM - the table it needs access to is locked. And that is the root of the problem.

I've only helped out one project that uses Summary Fields extension and that was quite intense - jobs take a long time to run on a busy / extensive db. Staff was unable to do anything in their CiviCRM during the day until I isolated the problem and moved their Summary Fields extension job to a designated cron to run once during a designated window during the night. And by that I mean -> Disable the job in the CiviCRM UI - Scheduled Jobs and instead call it specifically via a crontab. If you do that for both the Recurring Contributions job and for Summary Fields job then you can clearly separate them to ensure they can not collide anymore. The additional benefit is that frequency can't switch back unexpectedly to defaults (like what happened in your case) - and there is no drift. That cron will run e.g. 3am exactly every night.

What exactly that looks like depends on how you run crons on your site (and whether it's a Drupal or Wordpress, etc.) -> -> https://docs.civicrm.org/sysadmin/en/latest/setup/jobs/

Example from one of our clients: iATS Recurring runs at 5am every day ->

# apache crontab for drupal/civicrm
0 5 * * * /usr/bin/php /usr/local/bin/drush-7/vendor/bin/drush.php --root='/var/www/platform/example/' --uri='https://example.org' -u 1 civicrm-api job.iatsrecurringcontributions auth=0 -y

And when checking their Contributions generated last night -> note the time: 5:01am

I was thinking of something like this, but perhaps there are other issues with this approach. This is pseudocode.

forall recur_contributions where (contribution_status_id != Attempting and != Pending) {
  dbresult = SetContributionStatusId = Attempting
  if (dbresult == success) {
    result = SendRequestToiATS()
    if (result == success) {
      SetContributionStatusId = Pending
    } else {
      notifyUserByEmail("iATS Contribution Error")
      SetContributionStatusId = Failed
    }
  } else {
    notifyUserByEmail("Civi Database Error")
  }
}

iATSPayments / com.iatspayments.civicrm

Duplicate recurring contributions - "Failure, Error message: Expected one Contribution but found 0" #258