claimItem in the database and memory queues does not use expire correctly

Here's a failing test patch without the fix to show the problem more clearly.

Yep, I'm on it. Just waiting to make sure that the last patch failed the way I intended. I've got the complete patch with your fix and my test ready to go.

Attaching patch from #2 including test from #7 (and renaming the patch to be correct :/ ).

Humm, oops, I didn't completely understand the test class when I wrote that test. The code I added was specific to the database queue, but that code also gets run in testing the memory queue.

Taking a look..

OK, I removed the DB query for expire in the test, since that makes no sense for the memory queue. The test is still valid the way it is, that was just an extra assertion. I found after doing this that the memory queue exhibits the same issue wherein it would not claim an item unless it's expiry was exactly 0. That fix is included as well.

One thing to be careful about. Once you fix this, another problem rears:

#2883819: Cron does not use lease time correctly when claiming item

That issue means that cron queue processing currently ignores any lease time that you give it, erroneously using a constant of 1 second lease time for any queue item claim. So even though lease times are properly checked now, items expire far sooner than typically expected.

We probably need both to make sure we don't break things temporarily. Not totally sure though.

I noticed this in D7.

Wondering if this was done deliberately so that looped claimItem()'s don't run forever and this is why they require a system_cron() execution to reset expired back to 0.

Perhaps a better option would be to keep the current setup, where claimItem() only pulls from expired = 0, and instead add a SystemQueue::resetLeases() function that does the same thing as the system_cron() code and can be called before a looped claimItem() (or in the loop, if you're being careful), which will allow expired items to be claimed, but prevent infinite loops.

Updating IS and title to reflect the current scope which also includes the Memory queue.

I found the original issue at #391340: Job queue API, and I don't see any comments specifically about why expiration clearing happens in cron. comment #98 did bring it up as a performance concern.

Something to note is that this is how all expiries work in Drupal. For example, caches are only cleared on cron and may be continued to be used past their expiry time (this comes up with the page cache). I'm guessing that's the source of this in the first place.

I think a good place to start would just be some improved documentation - I've been tripped up on this, I've seen other developers have the same confusions, and it's not how developers typically think of expired item handling.

One nice side effect of the current handling is that it encourages site owners to run cron more often. I've seen sites where cron has been needlessly disabled, or only run 2-3 times a day, due to incorrect perceptions about performance. Being able to say "the floor of queue expiries and page caches is your cron interval" is a strong argument in favour of running cron with reasonable intervals.

Luckily, I don't think expired handling is really part of the "public" queue API. Even though nearly all Drupal sites use database queues, there's no contract that cron has anything to do with a given queue implementation. IOW, I could see this potentially being committed to 8.5.x.

+ $queue1->claimItem(-3600);

This feels like a bit of hack, given that it violates the interface docs on claimItem(). It would be reasonable for a queue implementation to require only positive lease times and throw an \InvalidArgumentException otherwise. I think it would be OK if the test manually inserted a row.

Should this patch remove the system_cron implementation too? That may give us hints if we're breaking any other expectations by altering the claimItem() behaviour.

I think it's a good idea to incorporate two other issues in this issue:

• https://www.drupal.org/project/drupal/issues/2833657
• https://www.drupal.org/project/drupal/issues/2893933

Some observations:

1. When an item is claimed, expiration is set to the current time + the $lease_time, which is the argument of the Queue's ::claimItem(). Note that time() is used to get the actual time and not the time at the start of the request.
   1. Currently only items with expire == 0 can be claimed. Expiration is set to 0 with the system cron.
2. When cron = {time = x} is defined in the annotation of your QueueWorker plugin, the lease time is erroneously set to 1 second as mentioned by m4olivei. If the annotation is not set, then the default of 30 seconds is applied in both the database queue and the memory queue.
   1. see Cron.php:176 : $lease_time = isset($info['cron']['time']) ?: NULL ;
   2. The incorrect lease time was discussed in issue https://www.drupal.org/project/drupal/issues/2883819

3. 3. Currently the time indicated in the annotation of the QueueWorker plugin is incorrectly used for both lease time and cron execution time.

   1. Just to be clear: cron time is the time in which one single cron call can start claiming and processing items. Lease time is the expected time each item will take. If an item hasn't finished yet, it should not be possible to claim and process the item again until the lease is expired.
   2. Since the Lease time is 1 second in a lot of cases, a single item can be processed twice in subsequent cron calls, causing errors.
   3. This issue was discussed in https://www.drupal.org/project/drupal/issues/2833657

4. I agree that resetting lease times in the system_cron() is not only an akward place for it (it took me a while to find it), it also seems to be faulty:

   1. It currently doesn't release items in the Memory queue, since the MemoryQueue doesn't implement the QueueGarbageCollectionInterface.
      Expired but claimed items in the memory queue are never released it seems.

   2. It makes sense to me to let the Queue handle expiration and release itself.

My patch builds on the patch in #41, also fixing the 1 second lease time and the incorrect use of the cron time as lease time. It also adds a kernel test on a cron queue execution level to see if leases correctly expire.

A straight reroll against 8.8.x to run tests against while I review.

Identical to the above patch with some minor CS fixes.

A few questions.

1. QueueInterface defines a default lease time of 1 hour. Why is it 30 seconds for the cron worker? I'd be tempted to move the \Drupal\Core\Cron::DEFAULT_QUEUE_CRON_LEASE_TIME constant to QueueInterface and use 1 hour.
2. By selecting queue items that are "locked" via an expiry in the past, doesn't that open us up to a race condition if multiple queue workers are processing the queue? It reads like it'd be possible to have two workers get the same item.
3. In CronQueueTestLeaseTime: Can we add a class header doc to explain that the point of the worker is to ensure that queue items are never processed? Also, how about throwing \LogicException here, since if it's thrown code must be changed?

Adding a patch to reroll this against the lastest 8.7.x branch too, as the patch in #25 doesn't seem to apply anymore.

It's been a while, but:

QueueInterface defines a default lease time of 1 hour. Why is it 30 seconds for the cron worker? I'd be tempted to move the \Drupal\Core\Cron::DEFAULT_QUEUE_CRON_LEASE_TIME constant to QueueInterface and use 1 hour.

I would not move the constants to QueueInterface, as the constants are specific to CRON executing the queue, and doesn't apply generically to the QueueInterface.

You could consider using an hour instead of 30 seconds, I don't really have an opinion about that, other than that the 3600 seconds in QueueInterface is actually never used in Core as every implementation of that class overrides that value to become either 30 seconds (Database and Memory Queue) or 0 (BatchMemory).

Generally you would want to motivate people to build short-lasting queue jobs, creating jobs that take long generally means you should cut them up into smaller jobs. If you do need a long lease time, you can add the annotation. So 30 seconds is still in line with what's currently being used by core.

By selecting queue items that are "locked" via an expiry in the past, doesn't that open us up to a race condition if multiple queue workers are processing the queue? It reads like it'd be possible to have two workers get the same item

I need to think about that. My first thought would be that this happens in the DatabaseQueue which implements the ReliableQueueInterface, which maintains the order of the tasks being executed, if I'm not mistaken, so I'm not sure if the scenario that you're imagining is technically likely to happen.

Reroll for the 8.8.x branch

Thanks for the reroll @nuez

Just a bit of work here, with this QueueTest should come back green.

Rerolled for the 9.2.x branch and opened a MR.

In case anyone needs it, a reroll for the 9.1.x branch.

Fixed the broken tests on the 9.3.x reroll - https://git.drupalcode.org/project/drupal/-/merge_requests/254/diffs

Further review required. I've tested the patch, and it seems to be functional.

If accepted, I guess a change notice will be required for the new lease_time attribute as well as the introduction of the CronInterface::DEFAULT_QUEUE_CRON_TIME and CronInterface::DEFAULT_QUEUE_CRON_LEASE_TIME constants which can be used by other Cron implementations.

I rebased the branch against 9.4.x.

According to the #3222251: [November 8, 2021] Replace all isset constructs with the null coalescing operator and #2909370: Fix 'Drupal.Commenting.VariableComment.IncorrectVarType' coding standard issues, we cannot apply a patch from the #40 comment on the 9.3.x and 9.4.x branches.

An actual patch is attached to the comment.

Fixed code quality

Rerolled for 9.4, 9.5 reroll requires updating the target of the issue fork (which can only be done by the original creator @DieterHolvoet)

Updated the TEST-ONLY patch to remove reference to non-existent QueueWorkerManagerInterface::DEFAULT_QUEUE_CRON_LEASE_TIME constant.

One thing to note is whether when specifying the default lease_time, we should ensure that it's always larger than or equal to the current time.

i.e. If a custom queue time of 100 seconds is specified, and the lease_time is unspecified, the lease_time should probably default to 100/115 seconds rather than the default 30 seconds?

Address broken test which doesn't pass the static queue worker definition through the QueueWorkerManager definition processor.

Tried to fix #53 for 10.1.x.
Please review.

Re-rolling #53 for Drupal 9.5.x

Re-rolling again for 9.5.x

Created an issue for the unrelated, random, intermittent errors from ckeditor5: https://www.drupal.org/project/drupal/issues/3332456

Re-rolling for 10.1.x

Adding Needs subsystem maintainer review, and tagging @neclimdul who's listed for queue. We don't have subsystem maintainers for cron, and we don't have a queue component to tag the issue.

Patch applies. :-)

I'd suggest that we add @see tags from all the functions/variables we're changing to Drupal\Core\Queue\QueueInterface::claimItem() because it has an explanation of what a lease is. If there's some other, better explanation, we should @see that instead.

I'd RTBC for this other than the above. We're using the 9.5 patch in #58 in production, for queue/cron issues we're having in DKAN.

Re-roll for 11.x that also adds @see comments as suggested above.

Adjusting 11.x tests in new CronSuspendQueueDelayTest.php

Reroll for 11.x looks good, my concerns from #63 about @see are addressed.

Setting RTBC.

Hopefully we'll be able to backport this to 10.0 and/or 9.5.

I want to give a special tangential shout-out to #3068764: Refactor cron queue processing into its own class because I just spent a bunch of time trying to figure out a bespoke queue implementation that should have been an easy subclass of a generic queue handler. Tangent over.

+++ b/core/lib/Drupal/Core/Queue/DatabaseQueue.php
@@ -114,13 +114,19 @@ public function numberOfItems() {
-        $item = $this->connection->queryRange('SELECT [data], [created], [item_id] FROM {' . static::TABLE_NAME . '} q WHERE [expire] = 0 AND [name] = :name ORDER BY [created], [item_id] ASC', 0, 1, [':name' => $this->name])->fetchObject();
+        $item = $this->connection->queryRange('SELECT [data], [created], [item_id] FROM {' . static::TABLE_NAME . '} q WHERE (([expire] = 0) OR (:now > [expire])) AND [name] = :name ORDER BY [created], [item_id] ASC', 0, 1, [
+          ':name' => $this->name,
+          ':now' => \Drupal::time()->getCurrentTime(),
+        ])->fetchObject();

@@ -142,8 +148,7 @@ public function claimItem($lease_time = 30) {
-        ->condition('item_id', $item->item_id)
-        ->condition('expire', 0);
+        ->condition('item_id', $item->item_id);

Haven't made it all the way through this patch because I got hung up on this. I don't understand _why_ the change is needed. In addition if we read above the update the second block of code is part of we see the code is using the expire = 0 part of the condition to ensure only one process can claim an item. The current code will always succeed in updating removing this protection.

Doing some triage.

patch kill the issue, but need to find the core of error.

The 10.1.x patch from #62 doesn't apply to 10.2.x but the 11.x patch from #67 does, testing whether this still fixes the issue for me

Patch #67 seems to no longer apply cleanly to 10.3

This re-roll patch will cleanly apply the patch referenced in #67 to 10.3.x.
The main issue being QueueWorker being un-commented out in the two files listed:
core/modules/system/tests/modules/cron_queue_test/src/Plugin/QueueWorker/CronQueueTestDatabaseDelayException.php
and
core/modules/system/tests/modules/cron_queue_test/src/Plugin/QueueWorker/CronQueueTestLeaseTime.php

So the patch was looking for commented-out code where it has since been applied in 10.3.

Rerolled patch #75 for Drupal 10.3.6

Seems like a serious issue. I'd like to move this to the queue component because claimItem() bugs affect non-cron queues as well. Alas I dont think that component exists.

"bugs affect non-cron queues as well"
Do you have an example? I've not run into this issue and there's conceptual explanation but not real world examples.

Looks like the subsystem tag was added for me and I added the review so removing the tag.

I have just updated #75 patch to be compatible with 11.2.x branch. There was small change in comments, so composer couldn't find a place to apply chunk

I have just updated #75 patch to be compatible with 11.2.x branch. There was small change in comments, so composer couldn't find a place to apply chunk

Sorry, I have uploaded a wrong file. This one is correct.