iATS Duplicate recurring contributions, or contribution status not fetched

kelizoliva commented 4 years ago

This issue pretty much mirrors issue #258, however it was requested that I create a separate issue for this.

WordPress 5.2.3 CiviCRM 5.17.4 iATS Payments 1.6.2

For our client, we are occasionally seeing the following error a few times per month:

Aug 14 03:15:12  [info] $Unexpected Exception = CiviCRM_API3_Exception Object
(
    [extraParams:CiviCRM_API3_Exception:private] => Array
        (
            [is_error] => 1
            [error_message] => Expected one Contribution but found 0
            [error_code] => undefined
        )

    [message:protected] => Expected one Contribution but found 0
    [string:Exception:private] =>
    [code:protected] => 0
    [file:protected] => /var/www/website/public/wp-content/plugins/civicrm/civicrm/api/api.php
    [line:protected] => 45
    [trace:Exception:private] => Array
        (
            [0] => Array
                (
                    [file] => /var/www/website/public/wp-content/uploads/civicrm/ext/com.iatspayments.civicrm/iats.php
                    [line] => 1364
                    [function] => civicrm_api3
                    [args] => Array
                        (
                            [0] => Contribution
                            [1] => completetransaction
                            [2] => Array
                                (
                                    [id] => 80423
                                    [payment_processor_id] => 3
                                    [is_email_receipt] => 1
                                    [trxn_id] => ABD7EAEE:1565777711
                                    [receive_date] => 20190814031510
                                    [version] => 3
                                )

                        )

                )
[...]

We are seeing instances where contributions are sent to iATS for processing, are processed, but Civi is not updated with a completed status, so Civi attempts to run the contribution again, resulting in duplicate contributions.

Similarly, there are recurring contributions that complete in iATS, for which there is no record whatsoever in CiviCRM.

My read from issue #258 is that a "process may get interrupted with a payment actually happening but without civicrm being aware of it (and consequently repeating the payment request when it shouldn't)."

Please let me know if there is additional information that I can provide here!

adixon commented 4 years ago

Your error is occurring after the money has successfully been taken, and the code is trying to convert the pending contribution payment to a completed one. The iATS code is using an api function "completetransaction" to do this, but that attempt fails, so it logs it for you (which is what you found above). The error "expected one but found 0" suggests that the origin of the problem is earlier on - the pending contribution somehow wasn't created, or was deleted by some other process before it could be completed.

My best guess is that you'll find a server error of some kind around this time (e.g. the mysql to create the pending record failed for whatever reason, or you ran out of memory, or something).

Alternatively, you've got some other code that is deleting pending contributions when it shouldn't.

In your case, the payment request to iATS is not the issue, it's a different one.

Perhaps your recurring payments are being generated at the same time as a mysql backup is happening?

kelizoliva commented 4 years ago

I'll compare the error in civi to the server logs the next time this happens, as the last occurrence was on September 5th and the server logs only retain the past 30 days of data.

There is no code deleting contributions, this is a pretty vanilla civicrm instance.

Perhaps your recurring payments are being generated at the same time as a mysql backup is happening?

Perhaps, but one would assume that this would not matter, that the extension would be able to recover the data from iATS with a subsequent check. Anyhow, recurring payments all happen around 3:15 am, and there are no mysql backups running at this time.

The error above relates to transactions that result in duplicates. This error does not relate to the other issue where occasionally the recurring transaction does not show up at all in civi, but it is processed in iATS. There are no errors showing up that correspond to these instances.

KarinG commented 4 years ago

@kelizoliva -> so the workflow is: i) CiviCRM is creating a Contribution w/ status Pending (it does that for all payment processors) -> ii) then iATS kicks in to attempt the payment -> iii) upon return we attach the result to that Contribution w/ status Pending using the completetransaction API which then Completes the Contribution. In your case - completetransaction API can not find that initial Contribution to attach the payment result to.

You've ruled out backups - but do check your logs for other interference -> errors such as:[nativecode=1205 ** Lock wait timeout exceeded] provide clues that something is preventing that initial Contribution from being generated properly. That lock wait timeout is a symptom - but it will point you into the right direction (for example: smart groups/caching issues).

adixon commented 4 years ago

@KarinG - this one looks like a recurring contribution, so although your flow is correct, we should note that the initial pending contribution is also created within the iATS extension in this case.

I recall that the error "Expected one contribution and found 0" is misleading - it's an error that's being passed back from within a few layers of the completecontribution api call. But as Karin notes, you should see whatever is really causing the error generating another line in the debug file.

kelizoliva commented 4 years ago

There are two things going on with contributions:

1.) Occasionally recurring contributions clear in iATS but there is no record of the transaction in CiviCRM. For example, there is a transaction in iATS on 9/21/19 at 3:15am for $10 - It processed in iATS, but in civi there is no recurring record on that date (but the transaction has successfully recurred in previous months).

There is an error in the Civi logs:

Sep 21 03:15:06  [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 <= '20190921031506'
       [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 <= '20190921031506'
       [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 <= '20190921031506'
       [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)

and then

Sep 21 03:15:06  [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 <= '20190921031506'

and then

Sep 21 03:15:07  [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_cache1075
       [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_cache1075
       [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_cache1075
       [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)

and finally:

Sep 21 03:15:07  [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_cache1075

Sep 21 03:15:07  [info] Contribution record updated successfully

Looking in civi at contribution records for 9/21/19, there are no records.

2.) Occasionally recurring contributions clear in iATS, but do not show up in CiviCRM, but the next day they clear again in iATS and then show up in Civi. For example, there is a transaction in iATS on 9/5/19 for $2 at 3:15:08 PM. The transaction never shows up in CiviCRM. In the Civi logs I see:

And I'm not going to post that entire error message because it about a thousand or so lines long.

and then:

Sep 05 03:15:12  [info] Contribution record updated successfully

Sep 05 03:15:12  [info] Success: Database updated

Sep 05 03:15:12  [info] Contribution record updated successfully

Sep 05 03:15:13  [info] Receipt sent

Sep 05 03:15:13  [info] Success: Database updated

Sep 05 03:15:15  [info] Contribution record updated successfully

Sep 05 03:15:15  [info] Success: Database updated

Sep 05 03:15:15  [info] Contribution record updated successfully

Sep 05 03:15:16  [info] Receipt sent

Sep 05 03:15:16  [info] Success: Database updated

Sep 05 03:15:16  [info] Contribution record updated successfully

Sep 05 03:15:16  [info] Success: Database updated

Sep 05 03:15:16  [info] Contribution record updated successfully

In this case it was the first two transactions that had issues (there was another just before it with the same issue/error as described in scenario 1), and then all other transactions completed.

KarinG commented 4 years ago

@kelizoliva -> ah - so the issue is the deadlock in your database:

[debug_info] => INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)
        SELECT DISTINCT id, group_id FROM civicrm_temp_group_contact_cache1075
       [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]

This explains what's going on. When there is a deadlock it means the Contribution can't get Created. You would likely have the same issue trying to create the Contribution manually and/or Editing a Contact at that moment in time when there is a deadlock in your database. Task is to find out what causes the deadlocks.

I recently added some quick tips for dealing with deadlocks in CiviCRM on stackexchange: quite often Smart Groups are the underlying cause:

https://civicrm.stackexchange.com/questions/33410/update-db-query-fails-sporadically-when-saving-contact-nativecode-1205-lock/33411 - Note that Jon Goldberg also added more tips and a handy script here that will help you diagnose which Smart Groups are causing the deadlock.

Let me know if this helps you along.

kelizoliva commented 4 years ago

This could account for the September 21st example (where transactions are clearing in iATS but never appear in civi), however the second example, September 5th, is a different issue (where transactions are double-charged in iATS but are recorded only once in Civi) and does not involve a database deadlock.

Looking into the deadlocks, I tested Jon's script, and found that three of the smartgroups were hitting some permissions issues with the log file (why only three and not all 11 smart groups, I have no idea). Adjusted permissions and the script iterated through each smart group at about .03-.9 seconds apiece.

The groups that were hitting permissions issues when running the script are all disabled smart groups, so not really sure whether those should even be affecting the system at all if that is their status. I do however see that a deadlock in the database on October 4th does relate to one of these disabled smart groups. I'll be monitoring the logs following this change for further deadlocks related to smart groups, but I am hopeful that this issue is now resolved.

The other issue (september 5th example), where contributions are running twice in iATS but only recorded once in Civi, would appear to directly relate to the log issue "Expected one Contribution but found 0", which is then followed by a string of successful recurring contributions, where the that first contribution in the string is never recorded in civi, and thus run again (and charged again) the following day. There are no database deadlocks whatsoever surrounding this other issue.

KarinG commented 4 years ago

@kelizoliva - glad to hear you're on the right track resolving your deadlocks.

Re: "Expected one Contribution but found 0"- it's not impossible that this error is also related to the issues you had with Smart Groups; it really just means the contribution record that should have been created before we get to that section - could not be created (for some reason); But it's possible there is a different reason why that contribution record could not be created;

Continue to watch your recurring contributions job (and Smart Groups) closely by examining the next_scheduled_date - using our report template or just by checking the database directly. If you notice a next_scheduled_date in the past; then a) you have the ability to prevent a double charge [by editing that date] - but b) most importantly you have a specific recur_id to investigate. Find out everything there is to know about that recurring series - what makes it different from the others that do process?

kelizoliva commented 4 years ago

Thank you for the additional feedback Karin. The report with the next recurring contribution date column has been helpful! We did observe the issue of multiple charges recur between December 22nd-Dec26th (very convenient timing as it was not being watched), and it was a result of a database deadlock that referenced a specific smart group. There was nothing special about the query, so I am rather surprised that this smart group was the culprit, however I disabled it and cleared caches, and overnight there was the following deadlock reported in the logs:

Dec 27 03:15:06  [error] $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 contact_id, group_id FROM civicrm_tmp_e_gccache_7d349c9ed4b15234c1396d8e1faf6ac9
       [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 contact_id, group_id FROM civicrm_tmp_e_gccache_7d349c9ed4b15234c1396d8e1faf6ac9
       [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 contact_id, group_id FROM civicrm_tmp_e_gccache_7d349c9ed4b15234c1396d8e1faf6ac9
       [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)

In the backtrace there was:

#5 /var/www/website/public/wp-content/plugins/civicrm/civicrm/packages/DB/common.php(1920): PEAR->__call("raiseError", (Array:7))
#6 /var/www/website/public/wp-content/plugins/civicrm/civicrm/packages/DB/mysqli.php(933): DB_common->raiseError(-1, NULL, NULL, "INSERT IGNORE INTO civicrm_group_contact_cache (contact_id, group_id)\n      ...", "1213 ** Deadlock found when trying to get lock; try restarting transaction")
#7 /var/www/website/public/wp-content/plugins/civicrm/civicrm/packages/DB/mysqli.php(403): DB_mysqli->mysqliRaiseError()

There were no gid's or cid's anywhere in the log of the error.

All transactions did appear to run smoothly, and there were no pending transactions with a date in the past when I checked today. Any thoughts on the above deadlock? Is it the civicrm_group_contact_cache table having issues? Thanks!

kelizoliva commented 4 years ago

Actually think I may see now. I reviewed the scheduled jobs, and saw that the 'Rebuild Smart Groups Cache' job was enabled, with bunk parameters in it. We had previously had this job disabled, and this is the second time it seems to have enabled itself without human intervention. This is a separate issue that we won't have the time to investigate, but I will be updating the parameters to something sane and leave it disabled. If it enables itself again, hopefully it will not trigger a deadlock after this.

KarinG commented 4 years ago

Hey @kelizoliva - sounds like you've made some good progress on diagnosing/working with Smart Group Cache issues! What CiviCRM Core/iATS Extension version are you on at the moment?

kelizoliva commented 4 years ago

Yes, clearing the database locks definitely prevented this issue from manifesting. This client is working with Civi 5.20.0 and iATS Payments 1.7.0, on WordPress 5.3.2.

We do manage a lot of Civi instances that use other payment processors, and have never seen anything like this with other processors; seems other processors are more graceful at handling disruptions. In this last event, there were 39 donors charged 4 times (over a four day period). Is there anything that can be done within the extension that would prevent this?

KarinG commented 4 years ago

The iATS Extension is the only Payment Processor in CiviCRM in which CiviCRM drives the recurring schedule/payments; This gives admins full control over recurring series including powerful options to change amounts/schedules/etc. Of course with more control on the CiviCRM side comes more admin responsibility/maintenance. The latest version of the iATS extension does change the sequence of operations (advance date then attempting payment and reverting date back when confirmed failed) - but the real issue you’ve run into are issues with your site config/database (eg the dead locks). These have caused more issues - perhaps not as noticeable. Glad you’re on your way to understanding the deadlocks and smart group cache issues better.

iATSPayments / com.iatspayments.civicrm

iATS Duplicate recurring contributions, or contribution status not fetched #283