Everlasting "pending jobs" in Craft 3.4+

Question

Everlasting "pending jobs" in Craft 3.4+

Closed this issue 4 years ago · 30 comments

Since upgrading various projects to Craft 3.4, the Queue Manager continually stacks up new pending tasks which never seem to run. I have had to disable Async Queue in order for that list to go.

Seems likely to be related to this breaking change: https://craftcms.com/guides/updating-plugins-for-craft-34#custom-queue-drivers

Answer 1 · 2020-02-12T16:16:57.000Z

Same here.

Answer 2 · 2020-02-14T15:23:21.000Z

Yikes just spotted this and a bit of a nightmare now after launch of site with lots of tasks. Is this a major refactor or could you point me in the direction where I might be able to temporarily patch this

Answer 3 · 2020-02-17T21:36:06.000Z

@MattWilcox @john-henry
I do not see a direct relation so far - needs a bit of testing.
Any specific jobs? Do you see a pattern?

Answer 4 · 2020-02-18T21:47:08.000Z

I've had to disable async queue on all my sites that run Craft 3.4. If I remember correctly, jobs would only run once, and subsequent jobs would stall and never run. So if I had async queue set up to run 2 jobs at a time, 2 jobs would run, then the rest would stall.

Answer 5 · 2020-02-19T11:31:00.000Z

@MattWilcox @john-henry
I did see a direct relation so far - needs a bit of testing.
Any specific jobs? Do you see a pattern?

No pattern that I know of, but we start all our new projects by cloning a base project; the base project exhibits the same issue, so everything else does. Just use Craft as usual... watch as no queued jobs get cleared.

Answer 6 · 2020-03-05T11:15:30.000Z

Same here.

Answer 7 · 2020-03-06T14:49:41.000Z

Any update on this? It has been a month.

What I did notice once when it hung, the cp page said the actual use was equal the pool concurrency but i could not find any job running.

Answer 8 · 2020-03-17T11:28:30.000Z

Also having this issue.

Answer 9 · 2020-03-17T15:16:20.000Z

Hey All,

I still can not reproduce the issue, but I'm on it.

Answer 10 · 2020-03-20T14:06:11.000Z

Also getting this. Disabled on all 3.4 sites at the moment.

Answer 11 · 2020-03-20T14:07:25.000Z

@roberttolton, @darylknight, @MattWilcox Can you provide any logs? web/queue/console.log - everything is important.

Answer 12 · 2020-03-20T14:12:54.000Z

Yes, but I don't think it contains anything useful. I cleared my logs, re-saved a section, and the job is now sitting there in the sidebar. Here's the contents of the only log file generated, web.log.

Stack trace:
#0 /home/[removed]/vendor/craftcms/cms/src/web/Controller.php(134): yii\web\Controller->beforeAction(Object(yii\base\InlineAction))
#1 /home/[removed]/vendor/yiisoft/yii2/base/Controller.php(155): craft\web\Controller->beforeAction(Object(yii\base\InlineAction))
#2 /home/[removed]/vendor/craftcms/cms/src/web/Controller.php(178): yii\base\Controller->runAction('edit-section', Array)
#3 /home/[removed]/vendor/yiisoft/yii2/base/Module.php(528): craft\web\Controller->runAction('edit-section', Array)
#4 /home/[removed]/vendor/craftcms/cms/src/web/Application.php(291): yii\base\Module->runAction('sections/edit-s...', Array)
#5 /home/[removed]/vendor/yiisoft/yii2/web/Application.php(103): craft\web\Application->runAction('sections/edit-s...', Array)
#6 /home/[removed]/vendor/craftcms/cms/src/web/Application.php(276): yii\web\Application->handleRequest(Object(craft\web\Request))
#7 /home/[removed]/vendor/yiisoft/yii2/base/Application.php(386): craft\web\Application->handleRequest(Object(craft\web\Request))
#8 /home/[removed]/public_html/index.php(21): yii\base\Application->run()
#9 {main}
2020-03-20 07:11:05 [-][8168][a839024c486744f0bf4364442f89361e][info][application] $_GET = [
    'p' => 'admin/settings/sections/1'
]

$_POST = []

$_FILES = []

$_COOKIE = [
    '_gcl_au' => '1.1.1535619805.1583225593'
    '_fbp' => 'fb.1.1583225593778.1342570182'
    'CRAFT_CSRF_TOKEN' => '••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••'
    '1031b8c41dfff97a311a7ac99863bdc5_username' => 'cb5220e69ba5fe21ba05a7fb2d099ec2f7233ed33a40b0e5ca5b7a4c7c7ff178a:2:{i:0;s:41:\"1031b8c41dfff97a311a7ac99863bdc5_username\";i:1;s:24:\"daryl@theengineisred.com\";}'
    'CraftSessionId' => 'a839024c486744f0bf4364442f89361e'
    '1031b8c41dfff97a311a7ac99863bdc5_identity' => '06ce3a341d120892875bcb484aacb7b9d0a23c29561a836a522e98cfdd2a69dfa:2:{i:0;s:41:\"1031b8c41dfff97a311a7ac99863bdc5_identity\";i:1;s:256:\"[\"8168\",\"[\\\"Q2G5X6au0FaD2lKe64lDaX18_rhaBdsxCD2Iqm3HbLHPdADhIvu3ZQsPV3zWgv6P60nuyHf8W7BVh4hDZPH5JVLjbREVLIopQ1D-\\\",null,\\\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36\\\"]\",1209600]\";}'
]

$_SESSION = [
    'bd62416aa8538ede709019a5e113eea5__flash' => []
    '1031b8c41dfff97a311a7ac99863bdc5__token' => '••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••'
    '1031b8c41dfff97a311a7ac99863bdc5__id' => '8168'
    '1031b8c41dfff97a311a7ac99863bdc5__expire' => 1584717071
]

$_SERVER = [
    'SERVER_SIGNATURE' => ''
    'BASE_URL' => 'http://[removed]'
    'SECURITY_KEY' => '••••••••••••••••••••••••••••••••'
    'BASE_PATH' => '/home/[removed]/public_html'
    'DB_DRIVER' => 'mysql'
    'UNIQUE_ID' => 'XnTO9NTLGxxZw@FGXqFuUAAAAFQ'
    'DB_PORT' => '3306'
    'REDIRECT_SCRIPT_URL' => '/admin/settings/sections/1'
    'DB_TABLE_PREFIX' => 'craft'
    'HTTP_USER_AGENT' => 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36'
    'SERVER_PORT' => '80'
    'REDIRECT_SCRIPT_URI' => 'http://[removed]/admin/settings/sections/1'
    'HTTP_ORIGIN' => 'http://[removed]'
    'HTTP_HOST' => '[removed]'
    'PHP_INI_SCAN_DIR' => '/opt/cpanel/ea-php73/root/etc:/opt/cpanel/ea-php73/root/etc/php.d:.'
    'DOCUMENT_ROOT' => '/home/[removed]/public_html'
    'SCRIPT_FILENAME' => '/home/[removed]/public_html/index.php'
    'REQUEST_URI' => '/admin/settings/sections/1'
    'SCRIPT_NAME' => '/index.php'
    'SCRIPT_URI' => 'http://[removed]/admin/settings/sections/1'
    'HTTP_CONNECTION' => 'keep-alive'
    'REMOTE_PORT' => '50635'
    'PATH' => '/bin:/usr/bin'
    'DB_DATABASE' => '[removed]'
    'SCRIPT_URL' => '/admin/settings/sections/1'
    'CONTEXT_PREFIX' => ''
    'PWD' => '/home/[removed]'
    'SERVER_ADMIN' => 'webmaster@[removed]'
    'DB_PASSWORD' => '••••••••••••'
    'REDIRECT_UNIQUE_ID' => 'XnTO9NTLGxxZw@FGXqFuUAAAAFQ'
    'REQUEST_SCHEME' => 'http'
    'REDIRECT_STATUS' => '200'
    'TZ' => 'America/New_York'
    'REDIRECT_QUERY_STRING' => 'p=admin/settings/sections/1'
    'HTTP_ACCEPT_LANGUAGE' => 'en-GB,en;q=0.9,fi;q=0.8,de;q=0.7,nl;q=0.6'
    'HTTP_REFERER' => 'http://[removed]/admin/settings/sections/1'
    'ENVIRONMENT' => 'staging'
    'HTTP_DNT' => '1'
    'HTTP_ACCEPT' => 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9'
    'DB_SERVER' => 'localhost'
    'REMOTE_ADDR' => '82.181.22.154'
    'SHLVL' => '1'
    'SERVER_NAME' => '[removed]'
    'CONTENT_LENGTH' => '1279'
    'DB_SCHEMA' => 'public'
    'SERVER_SOFTWARE' => 'Apache'
    'DB_USER' => '[removed]'
    'QUERY_STRING' => 'p=admin/settings/sections/1'
    'SERVER_ADDR' => '67.227.156.150'
    'GATEWAY_INTERFACE' => 'CGI/1.1'
    'HTTP_UPGRADE_INSECURE_REQUESTS' => '1'
    'SERVER_PROTOCOL' => 'HTTP/1.1'
    'HTTP_CACHE_CONTROL' => 'max-age=0'
    'HTTP_ACCEPT_ENCODING' => 'gzip, deflate'
    'REDIRECT_URL' => '/admin/settings/sections/1'
    'CONTENT_TYPE' => 'application/x-www-form-urlencoded'
    'REQUEST_METHOD' => 'POST'
    'HTTP_COOKIE' => '_gcl_au=1.1.1535619805.1583225593; _fbp=fb.1.1583225593778.1342570182; CRAFT_CSRF_TOKEN=c2d56c7f3b82622a854114a3b171caed9297b674a7e8588c726dc9f50afdc348a%3A2%3A%7Bi%3A0%3Bs%3A16%3A%22CRAFT_CSRF_TOKEN%22%3Bi%3A1%3Bs%3A211%3A%22HUztZYB27vQzceH8zqZM3uk-Y1TIglSGBMCYV81m%7C0166a84e4a51d2c604b439750869e50e8df025e083076a65ad46a0de834b0990HUztZYB27vQzceH8zqZM3uk-Y1TIglSGBMCYV81m%7C8168%7C%242y%2413%24R30FreKQz0gHC2I2ywANKuuauLf7h0Au7yaCWm0%2FtLVYrUXHJEtWW%22%3B%7D; 1031b8c41dfff97a311a7ac99863bdc5_username=cb5220e69ba5fe21ba05a7fb2d099ec2f7233ed33a40b0e5ca5b7a4c7c7ff178a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%221031b8c41dfff97a311a7ac99863bdc5_username%22%3Bi%3A1%3Bs%3A24%3A%22daryl%40theengineisred.com%22%3B%7D; CraftSessionId=a839024c486744f0bf4364442f89361e; 1031b8c41dfff97a311a7ac99863bdc5_identity=06ce3a341d120892875bcb484aacb7b9d0a23c29561a836a522e98cfdd2a69dfa%3A2%3A%7Bi%3A0%3Bs%3A41%3A%221031b8c41dfff97a311a7ac99863bdc5_identity%22%3Bi%3A1%3Bs%3A256%3A%22%5B%228168%22%2C%22%5B%5C%22Q2G5X6au0FaD2lKe64lDaX18_rhaBdsxCD2Iqm3HbLHPdADhIvu3ZQsPV3zWgv6P60nuyHf8W7BVh4hDZPH5JVLjbREVLIopQ1D-%5C%22%2Cnull%2C%5C%22Mozilla%2F5.0+%28Macintosh%3B+Intel+Mac+OS+X+10_15_3%29+AppleWebKit%2F537.36+%28KHTML%2C+like+Gecko%29+Chrome%2F80.0.3987.149+Safari%2F537.36%5C%22%5D%22%2C1209600%5D%22%3B%7D'
    'CONTEXT_DOCUMENT_ROOT' => '/home/[removed]/public_html'
    '_' => '/bin/nice'
    'PHP_SELF' => '/index.php'
    'REQUEST_TIME_FLOAT' => 1584713465.5952
    'REQUEST_TIME' => 1584713465
    'argv' => [
        0 => 'p=admin/settings/sections/1'
    ]
    'argc' => 1
]

Answer 13 · 2020-03-20T14:44:32.000Z

No, nothing useful. :-/
Does the Test Utility in the CP work? @darylknight
(slow queue processing is expected)

Answer 14 · 2020-03-20T15:30:54.000Z

We are also having the same issue and have disabled the plugin for now. We are instead running a cron job that does "queue/run". Yesterday however our queue was overflowing and we found out, by manually running the queue/run command, that we got a deadlock exception.

I am unsure if its related but it could be, maybe it would be good for @darylknight to also run the queue/run command from the command line to test?

The error we got was:

$ ./craft queue/run
Exception 'yii\db\Exception' with message 'SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
The SQL being executed was: UPDATE `nta_queue` SET `dateReserved`='2020-03-19 14:20:14', `timeUpdated`=1584627614, `attempt`=1 WHERE `id`='294052''

in /home/user_path/public_html/vendor/yiisoft/yii2/db/Schema.php:674

Error Info:
Array
(
    [0] => 40001
    [1] => 1213
    [2] => Deadlock found when trying to get lock; try restarting transaction
)

Stack trace:
#0 /home/user_path/public_html/vendor/yiisoft/yii2/db/Command.php(1295): yii\db\Schema->convertException(Object(PDOException), 'UPDATE `nta_que...')
#1 /home/user_path/public_html/vendor/yiisoft/yii2/db/Command.php(1091): yii\db\Command->internalExecute('UPDATE `nta_que...')
#2 /home/user_path/public_html/vendor/craftcms/cms/src/queue/Queue.php(591): yii\db\Command->execute()
#3 /home/user_path/public_html/vendor/craftcms/cms/src/queue/Queue.php(120): craft\queue\Queue->reserve()
#4 /home/user_path/public_html/vendor/craftcms/cms/src/queue/Command.php(77): craft\queue\Queue->run()
#5 [internal function]: craft\queue\Command->actionRun()
#6 /home/user_path/public_html/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#7 /home/user_path/public_html/vendor/yiisoft/yii2/base/Controller.php(157): yii\base\InlineAction->runWithParams(Array)
#8 /home/user_path/public_html/vendor/yiisoft/yii2/console/Controller.php(164): yii\base\Controller->runAction('run', Array)
#9 /home/user_path/public_html/vendor/yiisoft/yii2/base/Module.php(528): yii\console\Controller->runAction('run', Array)
#10 /home/user_path/public_html/vendor/yiisoft/yii2/console/Application.php(180): yii\base\Module->runAction('queue/run', Array)
#11 /home/user_path/public_html/vendor/craftcms/cms/src/console/Application.php(87): yii\console\Application->runAction('queue/run', Array)
#12 /home/user_path/public_html/vendor/yiisoft/yii2/console/Application.php(147): craft\console\Application->runAction('queue/run', Array)
#13 /home/user_path/public_html/vendor/yiisoft/yii2/base/Application.php(386): yii\console\Application->handleRequest(Object(craft\console\Request))
#14 /home/user_path/public_html/craft(22): yii\base\Application->run()
#15 {main}

Answer 15 · 2020-03-24T10:38:22.000Z

Can you watch out for the message Has not waited the lock. in your queue/console/web logs?

Answer 16 · 2020-03-24T10:53:44.000Z

I just ran the test utility & the jobs started processing once I saved another entry in the control panel. If I run the test utility, they will sit there until I do something to trigger the queue processing. If I run ./craft queue/run, it works and I don't get any errors.

Answer 17 · 2020-03-24T11:13:09.000Z

Thanks @darylknight!
I can not reproduce this with my test-app. It would be great to get the related logs:

Enable debugMode
tail -f storage/logs/web.log | grep ProcessPool

Answer 18 · 2020-03-24T11:25:49.000Z

darylknight@mordor boilerplate % tail -f storage/logs/web.log | grep ProcessPool
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (0 of 2, context: Async Queue Test Job 1)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::increment() (0 of 2, context: Async Queue Test Job 1)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (1 of 2, context: Async Queue Test Job 2)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::increment() (1 of 2, context: Async Queue Test Job 2)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 3)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 4)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 5)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 6)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 7)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 8)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 9)
2020-03-24 04:24:46 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Async Queue Test Job 10)
2020-03-24 04:25:02 [-][1][qf6eaicditv6n8gh6cbua7m7ng][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Updating search indexes)
2020-03-24 04:25:02 [-][1][qf6eaicditv6n8gh6cbua7m7ng][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Updating element slugs and URIs)
2020-03-24 04:25:02 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Updating search indexes)
2020-03-24 04:25:02 [-][1][-][trace][async-queue] ProcessPool::canIUse() (2 of 2, context: Generating pages sitemap)```

Answer 19 · 2020-03-24T22:57:14.000Z

@darylknight please try

composer require ostark/craft-async-queue:dev-reserved#a8b8d74f1af44441ad9dc6e48639770849397096

Answer 20 · 2020-03-25T09:01:25.000Z

With that version, those jobs start running as soon as I hit Run Test under utilities

Answer 21 · 2020-03-25T09:39:09.000Z

Sound good @darylknight. What about real-world jobs?

Anybody else who wants to give it a try?
@MattWilcox @john-henry @roberttolton @jsunsawyer

composer require ostark/craft-async-queue:dev-reserved#a8b8d74f1af44441ad9dc6e48639770849397096

Answer 22 · 2020-03-26T08:51:54.000Z

I hope this rewrite works better with Craft 3.4
f53f835

Answer 23 · 2020-03-30T19:30:17.000Z

Touch wood, I haven't seen this issue again. Nice one, thank you :)

Answer 24 · 2020-09-20T15:33:11.000Z

Is anyone seeing this in 3.5.x?

Answer 25 · 2020-09-21T08:20:40.000Z

@ademers I'm not aware of any issues with 3.5.x

Answer 26 · 2020-10-08T12:52:45.000Z

Same problem here in 3.5.x. Disabling the plugin even clears the queue.

Answer 27 · 2020-10-08T13:25:13.000Z

I've been meaning to create a separate issue, but haven't gotten around to it. In brief, the issue is related to a Sructure in multisite where the Structure is only enabled for one of the 2 sites. Disabling the plugin appears to resolve the issue. From the log:

2020-09-20 14:14:32 [-][-][-][error][craft\queue\QueueLogBehavior::afterError]  [3498] Updating element slugs and URIs (attempt: 1) - Error (time: 0.653s): Entry’s section (5) is not enabled for site 2
2020-09-20 14:14:32 [-][-][-][error][yii\base\InvalidConfigException] yii\base\InvalidConfigException: Entry’s section (5) is not enabled for site 2 in /srv/users/serverpilot/apps/example/vendor/craftcms/cms/src/elements/Entry.php:888

Answer 28 · 2020-10-08T13:44:35.000Z

Seems to be a different problem here, no Structure or multisite. ‘Updating Search Indexes’ relating to the order get stuck in the queue ahead of the order email going out. No errors reported in any of the logs. If I disable the plugin they clear straight away but no logged errors show.

Answer 29 · 2023-03-09T18:37:46.000Z

This is also happening on Version 4.4.0 with PHP 8.2.3. As soon as I disabled the plugin, it cleared right up.

It was also a clean install with 1 entry.

Answer 30 · 2024-06-14T18:45:24.000Z

Still having this on Version 4.10.0 with PHP 8.2.x. Similarly, disabled the plugin, and everything moved forward.

Obviously not a solution, because the reason I installed the plugin was so background tasks could work without the user logging in to the CP.