search

ostark / craft-async-queue

Async Queue Handler for Craft 3 and 4
MIT License
93 stars 7 forks source link

Everlasting "pending jobs" in Craft 3.4+ #27

Closed MattWilcox closed 4 years ago

MattWilcox commented 4 years ago

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

texasbaptists commented 4 years ago

Same here.

john-henry commented 4 years ago

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

ostark commented 4 years ago

@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?

jsunsawyer commented 4 years ago

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.

MattWilcox commented 4 years ago

@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.

lenvanessen commented 4 years ago

Same here.

alexthn commented 4 years ago

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.

roberttolton commented 4 years ago

Also having this issue.

ostark commented 4 years ago

Hey All,

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

darylknight commented 4 years ago

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

ostark commented 4 years ago

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

darylknight commented 4 years ago

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
]
ostark commented 4 years ago

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

alexthn commented 4 years ago

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}
ostark commented 4 years ago

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

darylknight commented 4 years ago

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.

ostark commented 4 years ago

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

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

darylknight commented 4 years ago 

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)```
ostark commented 4 years ago

@darylknight please try

composer require ostark/craft-async-queue:dev-reserved#a8b8d74f1af44441ad9dc6e48639770849397096
darylknight commented 4 years ago

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

ostark commented 4 years ago

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
ostark commented 4 years ago

I hope this rewrite works better with Craft 3.4 https://github.com/ostark/craft-async-queue/commit/f53f835f446afa7dbb5af8d42b0482ba3fbafbce

MattWilcox commented 4 years ago

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

ademers commented 4 years ago

Is anyone seeing this in 3.5.x?

ostark commented 4 years ago

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

jameslindeman commented 4 years ago

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

ademers commented 4 years ago

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
jameslindeman commented 4 years ago

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.

theurbanu commented 1 year ago

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.

nathansnelgrove commented 4 months ago

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.