Cache race conditions
A client was asking me to find out why a $2,500 donation failed. I found this error in the logs (full backtrace below):
Nov 10 10:58:40 [error] $Fatal Error Details = Array
(
[callback] => Array
(
[0] => CRM_Core_Error
[1] => exceptionHandler
)
[code] => -5
[message] => DB Error: already exists
[mode] => 16
[debug_info] => UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5OiJDb21wbGV0ZWQiO2k6MztzOjk6IkNhbmNlbGxlZCI7aTo0O3M6MTI6IkxlZnQgTWVzc2FnZSI7aTo1O3M6MTE6IlVucmVhY2hhYmxlIjtpOjY7czoxMjoiTm90IFJlcXVpcmVkIjtpOjc7czo5OiJBdmFpbGFibGUiO2k6ODtzOjc6Ik5vX3Nob3ciO2k6OTtzOjY6IlVucmVhZCI7aToxMDtzOjU6IkRyYWZ0Ijt9', created_date = FROM_UNIXTIME(1668095920), expired_date = FROM_UNIXTIME(1668117520) WHERE group_name = "metadata_5_54_1" AND path = "CRM_OG_activitystatus_883f1c0c1790789755f726d1e41232c2" [nativecode=1062 ** Duplicate entry 'metadata_5_54_1-CRM_OG_activitystatus_883f1c0c1790789755f726d...' for key 'UI_group_path_date']
[type] => DB_Error
[user_info] => UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5OiJDb21wbGV0ZWQiO2k6MztzOjk6IkNhbmNlbGxlZCI7aTo0O3M6MTI6IkxlZnQgTWVzc2FnZSI7aTo1O3M6MTE6IlVucmVhY2hhYmxlIjtpOjY7czoxMjoiTm90IFJlcXVpcmVkIjtpOjc7czo5OiJBdmFpbGFibGUiO2k6ODtzOjc6Ik5vX3Nob3ciO2k6OTtzOjY6IlVucmVhZCI7aToxMDtzOjU6IkRyYWZ0Ijt9', created_date = FROM_UNIXTIME(1668095920), expired_date = FROM_UNIXTIME(1668117520) WHERE group_name = "metadata_5_54_1" AND path = "CRM_OG_activitystatus_883f1c0c1790789755f726d1e41232c2" [nativecode=1062 ** Duplicate entry 'metadata_5_54_1-CRM_OG_activitystatus_883f1c0c1790789755f726d...' for key 'UI_group_path_date']
[to_string] => [db_error: message="DB Error: already exists" code=-5 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5OiJDb21wbGV0ZWQiO2k6MztzOjk6IkNhbmNlbGxlZCI7aTo0O3M6MTI6IkxlZnQgTWVzc2FnZSI7aTo1O3M6MTE6IlVucmVhY2hhYmxlIjtpOjY7czoxMjoiTm90IFJlcXVpcmVkIjtpOjc7czo5OiJBdmFpbGFibGUiO2k6ODtzOjc6Ik5vX3Nob3ciO2k6OTtzOjY6IlVucmVhZCI7aToxMDtzOjU6IkRyYWZ0Ijt9', created_date = FROM_UNIXTIME(1668095920), expired_date = FROM_UNIXTIME(1668117520) WHERE group_name = "metadata_5_54_1" AND path = "CRM_OG_activitystatus_883f1c0c1790789755f726d1e41232c2" [nativecode=1062 ** Duplicate entry 'metadata_5_54_1-CRM_OG_activitystatus_883f1c0c1790789755f726d...' for key 'UI_group_path_date']"]
)
In CRM_Core_OptionGroup::values()
, we check for a cached result. If we don't find one, we run the query, then cache the result. However, between the $cache->has()
and $cache->set()
, this value was added to the cache.
How to resolve?
It seems to me like there's no way to avoid a race condition without recovering gracefully from this error.
It seems like a failure to write to cache shouldn't be fatal - could we catch CRM_Utils_Cache_CacheException
and continue execution?
Backtrace
Nov 10 10:58:40 [debug] $backTrace = #0 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Error.php(954): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 /var/www/mysiten.org/vendor/pear/pear-core-minimal/src/PEAR.php(944): CRM_Core_Error::exceptionHandler(Object(DB_Error))
#2 /var/www/mysiten.org/vendor/pear/db/DB.php(997): PEAR_Error->__construct("DB Error: already exists", -5, 16, (Array:2), "UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#3 /var/www/mysiten.org/vendor/pear/pear-core-minimal/src/PEAR.php(575): DB_Error->__construct(-5, 16, (Array:2), "UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#4 /var/www/mysiten.org/vendor/pear/pear-core-minimal/src/PEAR.php(223): PEAR::_raiseError(Object(DB_mysqli), NULL, -5, 16, (Array:2), "UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...", "DB_Error", TRUE)
#5 /var/www/mysiten.org/vendor/pear/db/DB/common.php(1928): PEAR->__call("raiseError", (Array:7))
#6 /var/www/mysiten.org/vendor/pear/db/DB/mysqli.php(943): DB_common->raiseError(-5, NULL, NULL, "UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...", "1062 ** Duplicate entry 'metadata_5_54_1-CRM_OG_activitystatus_883f1c0c179078...")
#7 /var/www/mysiten.org/vendor/pear/db/DB/mysqli.php(413): DB_mysqli->mysqliRaiseError()
#8 /var/www/mysiten.org/vendor/pear/db/DB/common.php(1234): DB_mysqli->simpleQuery("UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#9 /var/www/mysiten.org/vendor/civicrm/civicrm-packages/DB/DataObject.php(2696): DB_common->query("UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#10 /var/www/mysiten.org/vendor/civicrm/civicrm-packages/DB/DataObject.php(1829): DB_DataObject->_query("UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#11 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/DAO.php(494): DB_DataObject->query("UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...")
#12 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/DAO.php(1675): CRM_Core_DAO->query("UPDATE civicrm_cache SET data = 'YToxMDp7aToxO3M6OToiU2NoZWR1bGVkIjtpOjI7czo5...", FALSE)
#13 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Utils/Cache/SqlGroup.php(137): CRM_Core_DAO::executeQuery("UPDATE civicrm_cache SET data = %1, created_date = FROM_UNIXTIME(%2), expired...", (Array:3), TRUE, NULL, FALSE, FALSE)
#14 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/OptionGroup.php(173): CRM_Utils_Cache_SqlGroup->set("CRM_OG_activitystatus_883f1c0c1790789755f726d1e41232c2", (Array:10))
#15 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/PseudoConstant.php(262): CRM_Core_OptionGroup::values("activity_status", FALSE, FALSE, FALSE, NULL, "name", FALSE, FALSE, "value", "weight")
#16 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/DAO.php(2837): CRM_Core_PseudoConstant::get("CRM_Activity_BAO_Activity", "status_id", (Array:8), "validate")
#17 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Utils/FormattingUtil.php(264): CRM_Core_DAO::buildOptions("status_id", "validate", (Array:10))
#18 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Generic/AbstractAction.php(530): Civi\Api4\Utils\FormattingUtil::getPseudoconstantList((Array:30), "status_id:name", (Array:10), "create")
#19 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Generic/Traits/DAOActionTrait.php(178): Civi\Api4\Generic\AbstractAction->formatWriteValues((Array:10))
#20 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Generic/DAOSaveAction.php(30): Civi\Api4\Generic\DAOSaveAction->formatWriteValues((Array:10))
#21 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Provider/ActionObjectProvider.php(69): Civi\Api4\Generic\DAOSaveAction->_run(Object(Civi\Api4\Generic\Result))
#22 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Kernel.php(149): Civi\Api4\Provider\ActionObjectProvider->invoke(Object(Civi\Api4\Generic\DAOSaveAction))
#23 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/Api4/Generic/AbstractAction.php(250): Civi\API\Kernel->runRequest(Object(Civi\Api4\Generic\DAOSaveAction))
#24 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/BAO/Contribution.php(552): Civi\Api4\Generic\AbstractAction->execute()
#25 /var/www/mysiten.org/vendor/civicrm/civicrm-core/api/v3/utils.php(1319): CRM_Contribute_BAO_Contribution::create((Array:23))
#26 /var/www/mysiten.org/vendor/civicrm/civicrm-core/api/v3/Contribution.php(87): _civicrm_api3_basic_create("CRM_Contribute_BAO_Contribution", (Array:23), "Contribution")
#27 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Provider/MagicFunctionProvider.php(89): civicrm_api3_contribution_create((Array:23))
#28 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Kernel.php(149): Civi\API\Provider\MagicFunctionProvider->invoke((Array:8))
#29 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Kernel.php(81): Civi\API\Kernel->runRequest((Array:8))
#30 /var/www/mysiten.org/vendor/civicrm/civicrm-core/api/api.php(133): Civi\API\Kernel->runSafe("Contribution", "create", (Array:10))
#31 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/BAO/Contribution.php(3848): civicrm_api3("Contribution", "create", (Array:10))
#32 /var/www/mysiten.org/vendor/civicrm/civicrm-core/api/v3/Contribution.php(522): CRM_Contribute_BAO_Contribution::completeOrder((Array:5), NULL, 21523, NULL)
#33 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Provider/MagicFunctionProvider.php(89): civicrm_api3_contribution_completetransaction((Array:9))
#34 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Kernel.php(149): Civi\API\Provider\MagicFunctionProvider->invoke((Array:8))
#35 /var/www/mysiten.org/vendor/civicrm/civicrm-core/Civi/API/Kernel.php(81): Civi\API\Kernel->runRequest((Array:8))
#36 /var/www/mysiten.org/vendor/civicrm/civicrm-core/api/api.php(133): Civi\API\Kernel->runSafe("contribution", "completetransaction", (Array:9))
#37 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/Form/Contribution/Confirm.php(2412): civicrm_api3("contribution", "completetransaction", (Array:9))
#38 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/Form/Contribution/Confirm.php(861): CRM_Contribute_Form_Contribution_Confirm->processFormSubmission("100769")
#39 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Form.php(573): CRM_Contribute_Form_Contribution_Confirm->postProcess()
#40 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/Form/Contribution/Main.php(1472): CRM_Core_Form->mainProcess()
#41 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Contribute/Form/Contribution/Main.php(1220): CRM_Contribute_Form_Contribution_Main->skipToThankYouPage()
#42 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Form.php(573): CRM_Contribute_Form_Contribution_Main->postProcess()
#43 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/QuickForm/Action/Upload.php(152): CRM_Core_Form->mainProcess()
#44 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/QuickForm/Action/Upload.php(119): CRM_Core_QuickForm_Action_Upload->realPerform(Object(CRM_Contribute_Form_Contribution_Main), "upload")
#45 /var/www/mysiten.org/vendor/civicrm/civicrm-packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Upload->perform(Object(CRM_Contribute_Form_Contribution_Main), "upload")
#46 /var/www/mysiten.org/vendor/civicrm/civicrm-packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Contribute_Form_Contribution_Main), "upload")
#47 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Controller.php(355): HTML_QuickForm_Page->handle("upload")
#48 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Invoke.php(319): CRM_Core_Controller->run((Array:3), NULL)
#49 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Invoke.php(69): CRM_Core_Invoke::runItem((Array:18))
#50 /var/www/mysiten.org/vendor/civicrm/civicrm-core/CRM/Core/Invoke.php(36): CRM_Core_Invoke::_invoke((Array:3))
#51 /var/www/mysiten.org/web/modules/contrib/civicrm/src/Civicrm.php(88): CRM_Core_Invoke::invoke((Array:3))
#52 /var/www/mysiten.org/web/modules/contrib/civicrm/src/Controller/CivicrmController.php(80): Drupal\civicrm\Civicrm->invoke((Array:3))
#53 [internal function](): Drupal\civicrm\Controller\CivicrmController->main((Array:3), "")
#54 /var/www/mysiten.org/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php(123): call_user_func_array((Array:2), (Array:2))
#55 /var/www/mysiten.org/web/core/lib/Drupal/Core/Render/Renderer.php(564): Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}()
#56 /var/www/mysiten.org/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php(124): Drupal\Core\Render\Renderer->executeInRenderContext(Object(Drupal\Core\Render\RenderContext), Object(Closure))
#57 /var/www/mysiten.org/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php(97): Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext((Array:2), (Array:2))
#58 /var/www/mysiten.org/vendor/symfony/http-kernel/HttpKernel.php(159): Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}()
#59 /var/www/mysiten.org/vendor/symfony/http-kernel/HttpKernel.php(81): Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object(Symfony\Component\HttpFoundation\Request), 1)
#60 /var/www/mysiten.org/web/core/lib/Drupal/Core/StackMiddleware/Session.php(58): Symfony\Component\HttpKernel\HttpKernel->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#61 /var/www/mysiten.org/web/core/lib/Drupal/Core/StackMiddleware/KernelPreHandle.php(48): Drupal\Core\StackMiddleware\Session->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#62 /var/www/mysiten.org/web/core/modules/page_cache/src/StackMiddleware/PageCache.php(106): Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#63 /var/www/mysiten.org/web/core/modules/page_cache/src/StackMiddleware/PageCache.php(85): Drupal\page_cache\StackMiddleware\PageCache->pass(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#64 /var/www/mysiten.org/web/core/lib/Drupal/Core/StackMiddleware/ReverseProxyMiddleware.php(48): Drupal\page_cache\StackMiddleware\PageCache->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#65 /var/www/mysiten.org/web/core/lib/Drupal/Core/StackMiddleware/NegotiationMiddleware.php(51): Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#66 /var/www/mysiten.org/vendor/stack/builder/src/Stack/StackedHttpKernel.php(23): Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#67 /var/www/mysiten.org/web/core/lib/Drupal/Core/DrupalKernel.php(709): Stack\StackedHttpKernel->handle(Object(Symfony\Component\HttpFoundation\Request), 1, TRUE)
#68 /var/www/mysiten.org/web/index.php(19): Drupal\Core\DrupalKernel->handle(Object(Symfony\Component\HttpFoundation\Request))
#69 {main}