Queue items only reserved by cron for 1 second

Re-roll

I tested this using a long-running queueworker similar to the one @cliddell posted in the description. Before the patch, starting two simultaneous cron runs with a single long-running queue item would cause the item to be processed twice. After the patch, the item is correctly only processed once.

Please note that this ONLY happens when you process the queue via cron; running the queueworker manually via drush queue:run (or, presumably, via other non-cron methods) does not trigger the faulty behavior.

The patch code looks good as well, and includes tests. +1 RTBC

+1 for this patch

It keeps the cron process from attempting to run a cron job already in progress. Without it, the same cron job gets picked up multiple times.

Thank you @cliddell

I verified this patch works as well. I can't trigger the same queue runner with multiple cron runs after applying.

This would be a great addition to core!

Needs work as listed this is more of a feature than a bugfix at the moment with some possible scope creep.

The cron time and the lease time are incorrectly using the same value defined in the annotation of the queue worker.

There actually is not anything wrong with this IMHO. When claiming an item the lease_time is the max time you may hold onto it before someone else may claim it.

For the first item claimed in the run it could legitimately be held the entire time of the queue worker and no other tasks are permitted to run. If the task finishes early the QueueWorker releases the lock and no harm is done.

I also wonder if this might have been done to avoid fast failures from causing a claim loop, if instead the claim time was guaranteed to last the entire time of the QueueWorker run there is no chance of trying to claim the same queue item twice in the same execution preventing a loop of failures, however that is speculation on my part at the moment without digging deeper into the code and history.

The cron time and lease time are not actually being set to the same value. $cron_time is being set to the value of the queue worker cron time annotation, while $lease_time is being set to isset($info['cron']['time']) ?: NULL;, or TRUE since $info['cron']['time'] is always set, and later coerced to 1.

The difference between isset($info['cron']['time']) ?: NULL; and isset($info['cron']['time']) ? $info['cron']['time'] : NULL; OR $info['cron']['time'] ?: NULL; when written is what stops this from working with the current code (the NULL is an issue as well and should be sure to pickup a default value somewhere). This is basically an "incorrect value assignment" bug, we generally do not need to add new config options to fix an assignment fault.

It does seem that lease time was intended to prevent multiple cron processes from picking up the same queue item, however there are other checks in place to prevent a queue from picking up the same item in a loop unintentionally.

The DatabaseQueue and MemoryQueue queues will only process items with a lease_time of 0 (see the ::claimItem() method for each class). Lease time is set to 0 for all items with expired leases at the beginning of a cron run.

Ah you are correct about this for the default core queues. However this will not hold true for other Queue backends such as RabbitMQ that can implement actual timing on the locks.

The Database and Memory queue are very simple backends intended to work for many cases, being forced to implement features in unique ways since they are not full queue systems.

I can imagine a scenario where defining a separate queue item lease time would have an advantage over just using a queue's "cron time". For example, if someone had a queue worker which might process an item for up to 5 minutes, but didn't want to continue picking up new items after 3 minutes.

I could see this, though that becomes a feature request not a bugfix as there is currently no provision to provide a lease time nor any sign to indicate that was intended to be allowed for the QueueWorker.

I believe if you decrease this patch to just the one line of Cron.php to correctly calculate the lease_time and add any necessary tests to catch this issue you will have a better chance of this being more rapidly adopted into core. After this is adopted you could targeted the feature of adding lease_time as a config option.

This looks good to me. Logic takes care to use a default value or to pull in the cron run time.

The build failure appears to be an issue in DrupalCi (error about task run twice) I saw no errors reported from any of the actual tests.

I think this may still need a fail test? Leaving as NR for second opinion on that.

+ $lease_time = $info['cron']['time'] ?? self::DEFAULT_QUEUE_CRON_TIME;

The ?? part is not necessary because

  protected function processQueues() {
    // Grab the defined cron queues.
    foreach ($this->queueManager->getDefinitions() as $queue_name => $info) {
      if (isset($info['cron'])) {

and if (isset($info['cron'])) { then time is set by the queue manager:

  public function processDefinition(&$definition, $plugin_id) {
    parent::processDefinition($definition, $plugin_id);

    // Assign a default time if a cron is specified.
    if (isset($definition['cron'])) {
      $definition['cron'] += [
        'time' => 15,
      ];
    }
  }

Indeed, this caused the bug to always manifest because the isset() was guaranteed to be TRUE.

OTOH

$end = time() + $info['cron']['time']

If we are patching anyways , then shouldn't this be

$end = \Drupal::time()->getCurrentTime() + $info['cron']['time']

And ?? isn't needed again.

Chx is right, and that check is always wrong and it is odd. It was added by #2705809: Queue garbage collection is not correctly run on cron and there was some churn around testing claimItems so... maybe something weird was happening with tests back then and breaking this "fixed" it? Hard to peer pack that long but its definitely broken.

On the general approach, I think moving the value to a constant is fine, but we need to align the processing code.

As far as the null coalescing, again I think chx is right that it shouldn't be needed. But if we want to be consistent with the safeguard in the run length code maybe document that it is just safeguards for bad definitions and @see the processing.

Side note, that safeguard isn't all that great because it protects against null but not 0. Don't put 0 in your cron time or you're likely to have a bad time because that while loop is going to be very short 🤣.

Oh, also I'm not too keen on all the time changes.

1) I don't know how its currently being wrangled but those time changes are going to conflict with #2902895: [meta][no patch] Replace uses of REQUEST_TIME and time() with time service.
2) I spent a good couple minutes hunting the actual fix before finding it. Thought this was just massaging time calls and adding a test at first which didn't make sense.
3) There's a pretty good argument the global calls are the wrong way to make this change and this isn't that issue. My argument would be that QueueDatabaseFactory is responsible for constructing and injecting dependencies into DatabaseQueue, of which time service is one of them. Since the factory lives on the container it should also get the service injected and pass it along.
4) Also it should include chx's suggested time() change.

Ah I see, that's correct. So, technically this is OO code and with the factory it does have access to the container so that wouldn't be the correct approach. But also looks like that's the approach already being used in this class so I'll just need to follow up to fix it in general. No action here unless you want to make me an issue so i don't forget 🤣

I think the only missing I can think of is maybe we should test the safeguard since that's part of what we're fixing? Add a worker with a negative and/or 0 time and make sure the code fixes it and runs correctly.

Thanks!

[Mentoring] + adding GiftofOpenSource tag

It looks like there is still a code review item to address based on @neclimdul's comment #34 so flipping to Needs work.

New test makes sense.

Committed and pushed 0fc50fa51d to 10.0.x and 7a35abe96e to 9.5.x and 652e1faf8a to 9.4.x and d218a382b9 to 9.3.x. Thanks!

I committed the patch and not the MR. And funnily enough the MR is much better. Whoops. Committing the MR now...

Committed and pushed 97d9a57d4e to 10.0.x and c88351cfa0 to 9.5.x and a8650ce147 to 9.4.x and a6bf9113b5 to 9.3.x. Thanks!