Page MenuHomePhabricator

Rash of errors consuming donations queue
Closed, ResolvedPublic4 Story Points

Description

donations_queue_consume-20180425-010701 sent out 32 failmails, all with the same pattern:

A donation from the audit file (NL iDEAL donations mostly all come in via audit) is inserted, but there are a couple of errors. First we see

WD wmf_civicrm: Error inserting contribution: contact_id is not valid: XXXXYYYY

Then we see this error:

Cannot add or update a child row: a foreign key constraint fails (`civicrm`.`wmf_contribution_extra`, CONSTRAINT `FK_wmf_contribution_extra_entity_id` FOREIGN KEY (`entity_id`) REFERENCES `civicrm_contribution` (`id`) ON DELETE CASCADE)]',

So somehow we're trying to insert the contribution, and it's failing because it can't find the contact, but we keep going and try to insert a wmf_contribution_extra row which fails 'cause it can't find the contribution.3696c652e

Event Timeline

Ejegg created this task.Apr 25 2018, 2:01 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 25 2018, 2:01 AM
Ejegg triaged this task as Unbreak Now! priority.Apr 25 2018, 3:28 AM

Dang, this is also affecting the Ingenico recurring charge jobs. Those might be more serious - I'm afraid that if we fail inserting those donations, the next run will try to charge them again. Turned that job off for now, but we need to fix this ASAP.

Restricted Application added subscribers: Liuxinyu970226, TerraCodes. · View Herald TranscriptApr 25 2018, 3:28 AM
Ejegg added a comment.Apr 25 2018, 3:31 AM

Weird, those two users with anime avatars subscribe to all the Unbreak Now tasks?

This seems to relate to deadlocks - it's possible there was a notable db event occuring - but it's also possible the triggers on wmf_contribution_extra are a bit too expensive & we should ditch those ones in favour of calculating in the Post hook where we do the contribution extra - there is an inherent cost to the 'last currency' , 'last amount' in mysql that a php update might mitigate - ie the join on receive_date becomes required here & perhaps that would be better in php.

UPDATE civicrm_contribution cont
INNER JOIN wmf_donor donor ON donor.entity_id = cont.contact_id
SET donor.last_donation_currency = NEW.original_currency, donor.last_donation_amount = NEW.original_amount
WHERE cont.id = NEW.entity_id AND cont.receive_date = donor.last_donation_date
AND cont.contribution_status_id = 1;
Apr 24 17:07:02  [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 INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_amount`,`original_currency`,`entity_id` ) VALUES ( 'paypal_ec','3
xxx ,'2.00','EUR',xxx ) ON DUPLICATE KEY UPDATE gateway = 'paypal_ec',gateway_txn_id = 'xxxx',original_amount = '2.00',original_c
urrency = 'EUR' [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]


Apr 24 17:07:02  [info] $backTrace = #0 /srv/org.wikimedia.civicrm/civicrm/CRM/Core/Error.php(948): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 [internal function](): CRM_Core_Error::exceptionHandler(Object(DB_Error))
#2 /srv/org.wikimedia.civicrm/civicrm/packages/PEAR.php(921): call_user_func((Array:2), Object(DB_Error))
#3 /srv/org.wikimedia.civicrm/civicrm/packages/DB.php(985): PEAR_Error->__construct("DB Error: unknown error", -1, 16, (Array:2), "INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#4 /srv/org.wikimedia.civicrm/civicrm/packages/PEAR.php(575): DB_Error->__construct(-1, 16, (Array:2), "INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#5 [internal function](): PEAR->_raiseError(Object(DB_mysqli), NULL, -1, NULL, NULL, "INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...", "DB_Error", TRUE)
#6 /srv/org.wikimedia.civicrm/civicrm/packages/PEAR.php(224): call_user_func_array((Array:2), (Array:8))
#7 /srv/org.wikimedia.civicrm/civicrm/packages/DB/common.php(1927): PEAR->__call("raiseError", (Array:7))
#8 /srv/org.wikimedia.civicrm/civicrm/packages/DB/common.php(1927): PEAR->raiseError(NULL, -1, NULL, NULL, "INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...", "DB_Error", TRUE)
#9 /srv/org.wikimedia.civicrm/civicrm/packages/DB/mysqli.php(933): DB_common->raiseError(-1, NULL, NULL, NULL, "1213 ** Deadlock found when trying to get lock; try restarting transaction")
#10 /srv/org.wikimedia.civicrm/civicrm/packages/DB/mysqli.php(403): DB_mysqli->mysqliRaiseError()
#11 /srv/org.wikimedia.civicrm/civicrm/packages/DB/common.php(1238): DB_mysqli->simpleQuery("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#12 /srv/org.wikimedia.civicrm/civicrm/packages/DB/DataObject.php(2443): DB_common->query("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#13 /srv/org.wikimedia.civicrm/civicrm/packages/DB/DataObject.php(1635): DB_DataObject->_query("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#14 /srv/org.wikimedia.civicrm/civicrm/CRM/Core/DAO.php(399): DB_DataObject->query("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...")
#15 /srv/org.wikimedia.civicrm/civicrm/CRM/Core/DAO.php(1355): CRM_Core_DAO->query("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...", TRUE)
#16 /srv/org.wikimedia.civicrm/civicrm/CRM/Core/BAO/CustomValueTable.php(268): CRM_Core_DAO::executeQuery("INSERT INTO wmf_contribution_extra  ( `gateway`,`gateway_txn_id`,`original_am...", (Array:5))
#17 /srv/org.wikimedia.civicrm/civicrm/CRM/Core/BAO/CustomValueTable.php(660): CRM_Core_BAO_CustomValueTable::create((Array:1))
#18 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_civicrm/wmf_civicrm.module(161): CRM_Core_BAO_CustomValueTable::setValues((Array:5))
#19 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_civicrm/wmf_civicrm.module(3445): wmf_civicrm_set_custom_field_values(29602488, (Array:4))
#20 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_civicrm/wmf_civicrm.module(3369): wmf_civicrm_civicrm_post_Contribution("create", 29602488, Object(CRM_Cont
ribute_BAO_Contribution))
#21 /srv/org.wikimedia.civicrm/civicrm/CRM/Utils/Hook.php(282): wmf_civicrm_civicrm_post("create", "Contribution", 29602488, Object(CRM_Contribute_BAO_Contribut
ion))
#22 /srv/org.wikimedia.civicrm/civicrm/CRM/Utils/Hook/DrupalBase.php(85): CRM_Utils_Hook->runHooks((Array:65), "civicrm_post", 4, "create", "Contribution", 2960
2488, Object(CRM_Contribute_BAO_Contribution), NULL, NULL)
#23 /srv/org.wikimedia.civicrm/civicrm/Civi/Core/CiviEventDispatcher.php(98): CRM_Utils_Hook_DrupalBase->invokeViaUF(4, "create", "Contribution", 29602488, Obje
ct(CRM_Contribute_BAO_Contribution), NULL, NULL, "civicrm_post")
#24 [internal function](): Civi\Core\CiviEventDispatcher::delegateToUF(Object(Civi\Core\Event\PostEvent), "hook_civicrm_post", Object(Civi\Core\CiviEventDispatc
her))
#25 /srv/org.wikimedia.civicrm/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php(164): call_user_func((Array:2), Obj
ect(Civi\Core\Event\PostEvent), "hook_civicrm_post", Object(Civi\Core\CiviEventDispatcher))
#26 /srv/org.wikimedia.civicrm/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php(53): Symfony\Component\EventDispatc
her\EventDispatcher->doDispatch((Array:2), "hook_civicrm_post", Object(Civi\Core\Event\PostEvent))
#27 /srv/org.wikimedia.civicrm/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/ContainerAwareEventDispatcher.php(167): Symfony\Compone
nt\EventDispatcher\EventDispatcher->dispatch("hook_civicrm_post", Object(Civi\Core\Event\PostEvent))
#28 /srv/org.wikimedia.civicrm/civicrm/Civi/Core/CiviEventDispatcher.php(47): Symfony\Component\EventDispatcher\ContainerAwareEventDispatcher->dispatch("hook_ci
vicrm_post", Object(Civi\Core\Event\PostEvent))
#29 /srv/org.wikimedia.civicrm/civicrm/CRM/Utils/Hook.php(366): Civi\Core\CiviEventDispatcher->dispatch("hook_civicrm_post", Object(Civi\Core\Event\PostEvent))
#30 /srv/org.wikimedia.civicrm/civicrm/CRM/Contribute/BAO/Contribution.php(260): CRM_Utils_Hook::post("create", "Contribution", 29602488, Object(CRM_Contribute_
BAO_Contribution))
#31 /srv/org.wikimedia.civicrm/civicrm/CRM/Contribute/BAO/Contribution.php(518): CRM_Contribute_BAO_Contribution::add((Array:35), (Array:1))
#32 [internal function](): CRM_Contribute_BAO_Contribution::create((Array:35), (Array:1))
#33 /srv/org.wikimedia.civicrm/civicrm/api/v3/utils.php(1288): call_user_func_array((Array:2), (Array:2))
#34 /srv/org.wikimedia.civicrm/civicrm/api/v3/Contribution.php(86): _civicrm_api3_basic_create("CRM_Contribute_BAO_Contribution", (Array:35), "Contribution")
#35 /srv/org.wikimedia.civicrm/civicrm/Civi/API/Provider/MagicFunctionProvider.php(89): civicrm_api3_contribution_create((Array:35))
#36 /srv/org.wikimedia.civicrm/civicrm/Civi/API/Kernel.php(169): Civi\API\Provider\MagicFunctionProvider->invoke((Array:9))
#37 /srv/org.wikimedia.civicrm/civicrm/Civi/API/Kernel.php(100): Civi\API\Kernel->runRequest((Array:7))
#38 /srv/org.wikimedia.civicrm/civicrm/api/api.php(43): Civi\API\Kernel->runSafe("Contribution", "Create", (Array:26))
#39 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_civicrm/wmf_civicrm.module(474): civicrm_api3("Contribution", "Create", (Array:25))
#40 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_civicrm/wmf_civicrm.module(311): _wmf_civicrm_message_contribution_insert((Array:59))
#41 /srv/org.wikimedia.civicrm/sites/all/modules/queue2civicrm/DonationQueueConsumer.php(62): wmf_civicrm_contribution_message_import((Array:59))
#42 [internal function](): queue2civicrm\DonationQueueConsumer->processMessage((Array:29))
#43 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_common/WmfDatabase.php(28): call_user_func_array((Array:2), (Array:1))
#44 /srv/org.wikimedia.civicrm/sites/all/modules/wmf_common/TransactionalWmfQueueConsumer.php(24): WmfDatabase::transactionalCall((Array:2), (Array:1))
#45 [internal function](): wmf_common\TransactionalWmfQueueConsumer->processMessageWithErrorHandling((Array:29))
#46 /srv/org.wikimedia.civicrm/vendor/coderkungfu/php-queue/src/PHPQueue/Backend/Predis.php(126): call_user_func((Array:2), (Array:29))
#47 [internal function](): PHPQueue\Backend\Predis->PHPQueue\Backend\{closure}(Object(Predis\Transaction\MultiExec))
#48 /srv/org.wikimedia.civicrm/vendor/predis/predis/src/Transaction/MultiExec.php(431): call_user_func(Object(Closure), Object(Predis\Transaction\MultiExec))
#49 /srv/org.wikimedia.civicrm/vendor/predis/predis/src/Transaction/MultiExec.php(368): Predis\Transaction\MultiExec->executeTransactionBlock(Object(Closure))
#50 /srv/org.wikimedia.civicrm/vendor/predis/predis/src/Client.php(477): Predis\Transaction\MultiExec->execute(Object(Closure))
#51 /srv/org.wikimedia.civicrm/vendor/predis/predis/src/Client.php(401): Predis\Client->createTransaction((Array:3), Object(Closure))
#52 /srv/org.wikimedia.civicrm/vendor/predis/predis/src/Client.php(461): Predis\Client->sharedContextFactory("createTransaction", (Array:2))
#53 /srv/org.wikimedia.civicrm/vendor/coderkungfu/php-queue/src/PHPQueue/Backend/Predis.php(128): Predis\Client->transaction((Array:3), Object(Closure))
#54 /srv/org.wikimedia.civicrm/vendor/wikimedia/smash-pig/Core/QueueConsumers/BaseQueueConsumer.php(98): PHPQueue\Backend\Predis->popAtomic((Array:2))
#55 /srv/org.wikimedia.civicrm/sites/all/modules/queue2civicrm/queue2civicrm.module(140): SmashPig\Core\QueueConsumers\BaseQueueConsumer->dequeueMessages()
#57 /srv/org.wikimedia.civicrm/drupal/includes/module.inc(926): call_user_func_array("queue2civicrm_batch_process", (Array:0))
#58 /srv/org.wikimedia.civicrm/sites/all/modules/queue2civicrm/queue_consume.drush.inc(54): module_invoke("queue2civicrm", "batch_process")
#59 [internal function](): drush_queue_consume()
#60 /usr/share/php/drush/includes/command.inc(334): call_user_func_array("drush_queue_consume", (Array:0))
#61 /usr/share/php/drush/includes/command.inc(208): _drush_invoke_hooks("queue-consume", (Array:0), "queue_consume")
#62 [internal function](): drush_command()
#63 /usr/share/php/drush/includes/command.inc(175): call_user_func_array("drush_command", (Array:0))
#64 /usr/share/php/drush/drush.php(92): drush_dispatch((Array:28))
#65 /usr/share/php/drush/drush.php(61): _drush_bootstrap_and_dispatch()
#66 /usr/share/php/drush/drush.php(16): drush_main()
#67 {main}
Eileenmcnaughton added a comment.EditedApr 25 2018, 9:40 AM

Also - I use the practice in general in CiviCRM of creating a pending contribution before attempting to make a payment & then updating it when successful - maybe splitting out would mitigate rollback issues?

Change 429987 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Catch rollbacks between contrib and post hook

https://gerrit.wikimedia.org/r/429987

Change 429987 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Catch rollbacks between contrib and post hook

https://gerrit.wikimedia.org/r/429987

Ejegg closed this task as Resolved.May 8 2018, 8:04 PM
Vvjjkkii renamed this task from Rash of errors consuming donations queue to uaeaaaaaaa.Jul 1 2018, 1:13 AM
Vvjjkkii reopened this task as Open.
Vvjjkkii lowered the priority of this task from Unbreak Now! to High.
Vvjjkkii updated the task description. (Show Details)
Vvjjkkii removed subscribers: gerritbot, Aklapper.
Mainframe98 renamed this task from uaeaaaaaaa to Rash of errors consuming donations queue.Jul 1 2018, 8:11 AM
Mainframe98 closed this task as Resolved.
Mainframe98 raised the priority of this task from High to Unbreak Now!.
Mainframe98 updated the task description. (Show Details)
Mainframe98 added subscribers: Aklapper, gerritbot.
Restricted Application added a subscriber: Pcoombe. · View Herald TranscriptMay 21 2019, 9:32 PM
DStrine set the point value for this task to 4.Jun 4 2019, 3:54 AM