CiviCRM / donate middleware endpoint sometimes loses donations
While diagnosing donate-static#127 (closed), I stumbled upon a few CRITICAL log messages in /var/log/syslog
. One example is this:
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: [2023-10-16 02:33:52] donation_processor[342080].CRITICAL: (ea2d599) {"queue":"prod_web_donations","worker":{"logger":{}},"payload":{"class":"Tor\\Donation\\OneTimeContribution","args":[{"contact":{"email":"[REDACTED]@[REDACTED].net","firstName":"[REDACTED]","lastName":"[REDACTED]","shippingAddress":"[REDACTED]"},"perk":{"name":"none"},"misc":[],"payment_instrument_id":"Credit Card","currency":"USD","receive_date":"2023-10-16T02:33:47Z","total_amount":250,"trxn_id":"ch_[REDACTED]"}],"id":"4a5439bccd96b28f66a7c224f27ca53e","queue_time":1697423627.229118}} has failed {}
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]:
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: [2023-10-16 02:33:52] donation_processor[342080].ERROR: (ea2d599) Uncaught Exception CRM_Core_Exception: "SqlGroup: Failed to acquire lock on cache key." at /srv/crm.torproject.org/htdocs-prod/sites/all/modules/civicrm/api/api.php line 135
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: civicrm_api3() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/src/Civi/Api.php:14
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Tor\Civi\Api->api() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/src/Donation/Civi.php:18
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Tor\Donation\Civi->api() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/src/Donation/Civi.php:26
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Tor\Donation\Civi->findContribution() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/src/Donation/OneTimeContribution.php:28
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Tor\Donation\OneTimeContribution->perform() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/vendor/chrisboulton/php-resque/lib/Resque/Job.php:194
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Resque_Job->perform() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/vendor/chrisboulton/php-resque/lib/Resque/Worker.php:240
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Resque_Worker->perform() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/vendor/chrisboulton/php-resque/lib/Resque/Worker.php:202
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]: Resque_Worker->work() /srv/crm.torproject.org/htdocs-prod/sites/all/modules/custom/tor_donation/bin/processor:36
Oct 16 02:33:52 crm-int-01/crm-int-01 processor[342080]:
The actual name of that user was redacted, but I could confirm with @mattlav that the user's donation actually did go through. And because of a problem in CiviCRM (SqlGroup: Failed to acquire lock on cache key.
in this case), the donation did not get registered in CiviCRM at all.
We have a few of those, every day:
root@crm-int-01:~# zgrep -c CRITICAL.*prod /var/log/syslog*
/var/log/syslog:6
/var/log/syslog.1:6
/var/log/syslog.2.gz:2
/var/log/syslog.3.gz:3
/var/log/syslog.4.gz:2
/var/log/syslog.5.gz:1
/var/log/syslog.6.gz:2
/var/log/syslog.7.gz:6
Those need to be investigated to see how serious those are. The most critical issues are where (as above) a donation went through and didn't get registered in CiviCRM. It's particularly bad if they asked for a perk and didn't get it as well.
A few tasks for now
-
@anarcat investigate and classify all of the logged issues above (mostly cryptocurrency garbage, some lost donations) -
@mattlav compare the CiviCRM logs with the Stripe donation history to see if anything is missing -
@anarcat monitor logs during the week -
@smith test if we can unsubscribe from civicrm -
test if recurring donations work with paypal -
test if simple donations work with paypal (tested by @mathieu)
The errors we've had in the last 7 days are:
- 1 locking error (@mathieu?)
- 1 programming error, possibly fixed
- 1 mysterious paypal error
- 5 unsubscribe errors
- 20 cryptocurrency errors
- 28 errors total, or about 4 per day
Edited by mathieu