[4.x]: Deadlock found when updating searchindexqueue

[mmikkel]

What happened?

Description

Since updating sites to 4.15 and 5.7, we're regularly seeing failed UpdateSearchIndex jobs with the following error message:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction The SQL being executed was: UPDATE `craft_searchindexqueue` SET `reserved`=1 WHERE `id`=4033

Stack trace from the queue.log is here: https://pastebin.com/AHzTsDV1

The sites where this is happening are all running their queue jobs using Laravel Forge Deamons (e.g. Supervisord) with the following config (this is all Forge defaults):

[program:daemon-268341]
command=/usr/bin/nice -n 10 /usr/bin/php /home/forge/REDACTED-DOMAIN.com/craft queue/listen --verbose
process_name=%(program_name)s_%(process_num)02d
autostart=true
autorestart=true
user=forge
numprocs=1
startsecs=1
redirect_stderr=true
stdout_logfile=/home/forge/.forge/daemon-268341.log
stdout_logfile_maxbytes=5MB
stdout_logfile_backups=3
stopwaitsecs=10
stopsignal=SIGTERM
stopasgroup=true
killasgroup=true

runQueueAutomatically is set to false.

Steps to reproduce

Unfortunately, I haven't been able to reliably reproduce – we just keep finding these failed jobs in the queue manager 😢

Expected behavior

Actual behavior

Craft CMS version

4.15.4

PHP version

8.3.19

Operating system and version

No response

Database type and version

MySQL 8.0.42

Image driver and version

No response

Installed plugins and versions

No response

[brandonkelly]

Are you overriding the mutex component in config/app.php? If so, can you try removing that config?

[mmikkel]

Are you overriding the mutex component in config/app.php? If so, can you try removing that config?

Nope, not doing that on any of these sites 🫤 The only thing we have in app.php that isn't stock config is this:

'components' => [
    'queue' => [
        'ttr' => 86400, // let it run for a day, that's seems reasonable
    ]
]

[brandonkelly]

Do you happen to use read/write splitting for the database?

[mmikkel]

Do you happen to use read/write splitting for the database?

No.

[brandonkelly]

Alright, this one has me a little stumped. Best I can guess, a gap lock is causing the deadlock, but I’m not very confident about that.

I made the code a bit more defensive for the possibility that a deadlock occurs, and tagged Craft 4.15.6.1 and 5.7.8.2 with that. Hopefully it helps! 🤞

[mmikkel]

Well, I didn't give you a lot to work with on this one @brandonkelly – but thanks, this is much appreciated. I'll update here if this should keep cropping up going forward 🙏

[jornwildenbeest]

Hi @brandonkelly ,

We are getting the same error in a plugin where we are creating multiple drafts in 1 queue job to translate entries and then applying the draft.

What I've seen so far is that we only get the error when multiple queue worker are running.

The stack trace

Next yii\db\Exception: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
The SQL being executed was: INSERT INTO `searchindex` (`elementId`, `attribute`, `fieldId`, `siteId`, `keywords`) VALUES (888517, 'slug', 0, 69, ' temp lhjvbzbfwbdjanxxkbavhcdkmvyfveizysjs ') in /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/db/Schema.php:676
Stack trace:
#0 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/db/Command.php(1325): yii\db\Schema->convertException(Object(PDOException), 'INSERT INTO `se...')
#1 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/db/Command.php(1120): yii\db\Command->internalExecute('INSERT INTO `se...')
#2 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/helpers/Db.php(978): yii\db\Command->execute()
#3 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/services/Search.php(670): craft\helpers\Db::insert('{{%searchindex}...', Array)
#4 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/services/Search.php(188): craft\services\Search->_indexKeywords(Object(craft\elements\Entry), ' temp lhjvbzbfw...', 'slug')
#5 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/services/Elements.php(3571): craft\services\Search->indexElementAttributes(Object(craft\elements\Entry), Array)
#6 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/services/Elements.php(1651): craft\services\Elements->_saveElementInternal(Object(craft\elements\Entry), false, false, true, Array)
#7 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/services/Drafts.php(166): craft\services\Elements->duplicateElement(Object(craft\elements\Entry), Array)
#8 /Users/jorn/Sites/craft-plugins/craft-deepl/src/services/TranslationService.php(55): craft\services\Drafts->createDraft(Object(craft\elements\Entry), 1, 'Translation', 'Creating DeepL ...')
#9 /Users/jorn/Sites/craft-plugins/craft-deepl/src/jobs/TranslationJob.php(30): statikbe\deepl\services\TranslationService->translateEntry(888445, Object(craft\models\Site), Object(craft\models\Site), 1)
#10 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2-queue/src/Queue.php(243): statikbe\deepl\jobs\TranslationJob->execute(Object(craft\queue\Queue))
#11 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2-queue/src/cli/Queue.php(162): yii\queue\Queue->handleMessage('38229', 'O:34:"statikbe\\...', '300', '1')
#12 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2-queue/src/cli/Command.php(146): yii\queue\cli\Queue->execute('38229', 'O:34:"statikbe\\...', '300', '1', '37442')
#13 [internal function]: yii\queue\cli\Command->actionExec('38229', '300', '1', '37442')
#14 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#15 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/base/Controller.php(178): yii\base\InlineAction->runWithParams(Array)
#16 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/console/Controller.php(180): yii\base\Controller->runAction('exec', Array)
#17 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/console/ControllerTrait.php(90): yii\console\Controller->runAction('exec', Array)
#18 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/base/Module.php(552): craft\queue\Command->runAction('exec', Array)
#19 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/console/Application.php(180): yii\base\Module->runAction('queue/exec', Array)
#20 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/console/Application.php(91): yii\console\Application->runAction('queue/exec', Array)
#21 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/console/Application.php(147): craft\console\Application->runAction('queue/exec', Array)
#22 /Users/jorn/Sites/craft-site/vendor/craftcms/cms/src/console/Application.php(122): yii\console\Application->handleRequest(Object(craft\console\Request))
#23 /Users/jorn/Sites/craft-site/vendor/yiisoft/yii2/base/Application.php(384): craft\console\Application->handleRequest(Object(craft\console\Request))
#24 /Users/jorn/Sites/craft-site/craft(13): yii\base\Application->run()
#25 {main}
Additional Information:
Array
(
    [0] => 40001
    [1] => 1213
    [2] => Deadlock found when trying to get lock; try restarting transaction
)

Is this related to this issue?

PHP 8.3 and Craft CMS 4.16.1

[Thijmen]

Same here, we're getting the occasional deadlock on searchindexqueue every now and then. Multiple queue workers.

@brandonkelly can this get re-opened, or would you rather have a new issue?

[brandonkelly]

@Thijmen Are you overriding the mutex component config from config/app.php by chance? If so, can you try removing that?

[mmikkel]

We're also seeing this crop up from time to time still; I just haven't had the mind to update here 😔 FWIW, it seems to happen less frequently than it used to.

Configuration is the same as in the original issue (i.e. a single Supervisor queue worker, and no mutex overrides).

I know this isn't too helpful, but let me know if there's anything I can do to help hone in on the problem.

[Thijmen]

@Thijmen Are you overriding the mutex component config from config/app.php by chance? If so, can you try removing that?

Yes, and it is within my understanding that it is required if you are running on a load-balanced environment.

        'mutex' => function () use($redisHostEnvVar, $redisPortEnvVar, $redisPasswordEnvVar, $redisMutexIndexEnvVar) {
            $config = [
                'class' => craft\mutex\Mutex::class,
                'mutex' => [
                    'class' => yii\redis\Mutex::class,
                    // set the max duration to 15 minutes for console requests
                    'expire' => Craft::$app->request->isConsoleRequest ? 900 : 30,
                    'redis' => [
                        'hostname' => App::env($redisHostEnvVar) ?: 'localhost',
                        'port' => App::env($redisPortEnvVar) ?: 6379,
                        'database' => App::env($redisMutexIndexEnvVar) ?: 3,
                        'password' => App::env($redisPasswordEnvVar) ?: null,
                    ],
                ],
            ];

            // Return the initialized component:
            return Craft::createObject($config);
        },

Ofcourse, the environment variables for each queue-worker is the same.

[angrybrad]

Yes, and it is within my understanding that it is required if you are running on a load-balanced environment.

Nope - not required, and Redis does not make for a reliable global locking mechanism (like a mutex).

Comment that out so you're using Craft's default database-backed mutex and see if the behavior changes.

[jornwildenbeest]

@brandonkelly I think it is good to mention that we are not overwriting the mutex class and still get these locks when using multiple queue workers. I know it probably makes things not easier, but I thought you should know.

[Thijmen]

@brandonkelly I think it is good to mention that we are nog overwriting the mutex class and still get these locks when using multiple queue workers. I know it probably makes things not easier, but I thought you should know.

What database are you using and which version?

[jornwildenbeest]

@Thijmen Mysql v8.0.39 on a Ubuntu server.

[Thijmen]

Yeah MySQL here as well.

[angrybrad]

@jornwildenbeest

and still get these locks when using multiple queue workers

We generally recommend only using a single queue worker for exactly this reason - if you drop it down to one, does the behavior change?

[jornwildenbeest]

@angrybrad Yes everything works fine with only 1 queue worker. That is the fix we used, but things can get quite slow when you are working with thousands of entries.

So we ended up creating a separate queue worker for these tasks, so we can still run multipel workers for the default queue but the downside is that you can't see custom queue workers the craft queue overview in CP. There already is a discussion for this: https://github.com/craftcms/cms/discussions/13347

I just think that this isn't an ideal solution, and it would be great to see this fixed somehow! Either to see custom queue channels within the Craft CP or have this issue fixed.

Thanks a lot!

[mmikkel]

@angrybrad FWIW, we're using a single queue worker on all our sites (w/ the config in the original issue) and it's still happening, intermittently.

[thisisjamessmith]

I'm seeing this error cropping up too. Using a single systemd daemon.

[garycrane]

I've been seeing this on a few Craft 4 sites too.

Craft: 4.16.13 PHP: 8.0.30 Database: MariaDB 11.1.3

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction The SQL being executed was: UPDATE 'searchindexqueue' SET 'reserved'=0 WHERE 'id'=10912

Job Data:

{
    "elementType": "craft\\elements\\MatrixBlock",
    "elementId": 116404,
    "siteId": 1,
    "fieldHandles": null,
    "queued": true,
    "description": null
}

Also, we're not overriding the mutex component config from config/app.php

[johnwbaxter]

We're getting this on Craft 4 sites on Servd hosting too. And we are not doing any mutex config ourselves.

[Thijmen]

Can we re-open this issue?

[linear[bot]]

CMS-1621

[brandonkelly]

Those of you still experiencing this, please enable MySQL’s innodb_print_all_deadlocks setting, and then send in MySQL’s error log the next time the error occurs. That will give us a bit more to go on, so we can understand why this is happening in the first place.

[mmikkel]

Those of you still experiencing this, please enable MySQL’s innodb_print_all_deadlocks setting, and then send in MySQL’s error log the next time the error occurs. That will give us a bit more to go on, so we can understand why this is happening in the first place.

Just sent in an error log to support 🙏

Forgot to mention it in the email, but in this instance, the error occurred on a server running Craft 4.16.13 and a single supervisord queue runner.

[mmikkel]

We're still encountering this; lately it has been on an almost daily basis. Let me know if I can supply any additional info to help resolve it 🙏

[brandonkelly]

@mmikkel Just pushed up a potential fix for this, based on the logs you sent in. Can you please try changing your craftcms/cms requirement in composer.json to "dev-bugfix/17318-search-deadlock as 5.8.20" and let me know if that resolves it?

[mmikkel]

Thanks a lot @brandonkelly, that's much appreciated. Unfortunately I'm not able to actually reproduce the problem on demand, but I can get that commit deployed to a few of our sites that are affected the most, and I'll report back in some days if the errors stop occurring or not 🙏

[brandonkelly]

@mmikkel Any initial findings?