Make WordPress Core

Opened 7 years ago

Closed 6 years ago

#44818 closed defect (bug) (fixed)

cron: preventing duplicate events fails when the first event is too far in the past

Reported by: bodohugobarwich's profile bodohugobarwich Owned by: peterwilsoncc's profile peterwilsoncc
Milestone: 5.2 Priority: normal
Severity: normal Version: 2.7
Component: Cron API Keywords: has-patch has-unit-tests needs-refresh 5-2-early
Focuses: Cc:

Description (last modified by SergeyBiryukov)

the patch submitted in [29939]/#6966 fails when the timestamp of the first event is too far in the past, perhaps because the cron was not executed.

in src/wp-includes/cron.php :

if ( $next && abs( $next - $timestamp ) <= 10 * MINUTE_IN_SECONDS ) {
        return;
}

The same Event that has been scheduled in 2016 and was not processed since then
permits that any amount of those Events can be added in 1 second interval.

That way the database field "cron" in "wp_options" fills up with "do_ping" Events in 1 second interval until no further event can't be added due to MySQL packet_size restrictions.

$ date --date="1970-01-01 + 1464704077 sec" +"%F %T"
2016-05-31 15:14:37

$ php -r "echo abs( 1464704077 - time()) . \"\\n\";"
69813398
$ php -r "echo abs( 1464704077 - time()) . \" < \". (10*600) . \"\\n\";"
69813460 < 6000
$ php -r "echo (1464704077 - time()) . \" < \". (10*600) . \"\\n\";"
-69813728 < 6000

Attachments (6)

wordpres-44818_2018-09-28.diff (4.7 KB) - added by bodohugobarwich 6 years ago.
git-diff file of my local branch against the master on the files I modified
wordpress-44818_2018-10-01.diff (2.0 KB) - added by bodohugobarwich 6 years ago.
git-diff of the new test cases of past events against future events
wordpress-44818_2018-10-06.diff (7.0 KB) - added by bodohugobarwich 6 years ago.
git-diff of my local branch to the 5.0 branch
wordpress-44818_2018-10-06-2.diff (4.4 KB) - added by bodohugobarwich 6 years ago.
git-diff of the correction of uncommited changes
44818.diff (4.6 KB) - added by peterwilsoncc 6 years ago.
44818.2.diff (4.7 KB) - added by peterwilsoncc 6 years ago.
CS fix on previous patch.

Download all attachments as: .zip

Change History (32)

#1 @bodohugobarwich
7 years ago

It should be MINUTE_IN_SECONDS == 60 in the example code.

$ php -r "echo abs( 1464704077 - time()) . \" < \". (10*60) . \"\\n\";"
70070760 < 600

but even with a bigger number it still fails to recognize the past unexecuted event.

#2 @bodohugobarwich
7 years ago

Rather it should be the last scheduled Time of the similar Event:

$ date +"%s"
1534775409
$ php -r "echo \"last: 1534775409 < limit: \" . (time() + (10*60)) . \" => \" . (int)(1534775409 < (time() + (10*60))) . \"\\n\";"
last: 1534775409 < limit: 1534776745 => 1
$ date --date=" 2018-08-20 16:00" +"%s"
1534777200
$ php -r "echo \"last: 1534777200 < limit: \" . (time() + (10*60)) . \" => \" . (int)(1534777200 < (time() + (10*60))) . \"\\n\";"
last: 1534777200 < limit: 1534776723 => 0
Last edited 7 years ago by bodohugobarwich (previous) (diff)

#3 @peterwilsoncc
6 years ago

Hi @bodohugobarwich and welcome to trac!

If I understand correctly, you're saying that having an event scheduled in the past - for whatever reason - then the 10 minute limit does not apply.

For example, the my_cron_hook schedule could be:

  • 1/1/2016 12:00:00
  • 1/1/2028 12:00:00

The bug is that a developer could then schedule my_cron_hook within a second of one of the future at 1/1/2028 12:00:01.

Please correct me if I have misunderstood.

Last edited 6 years ago by peterwilsoncc (previous) (diff)

#4 @bodohugobarwich
6 years ago

Yes, exactly.

If you have my_cron_hook scheduled for 1/1/2016 12:00:00 and 1/1/2028 12:00:00

the function:

wp_next_scheduled($hook, $args);

returns allways the timestamp of the first event which would be 1451649600

Thus the Function continues running and accepts 1/1/2028 12:00:01 as next valid timestamp

$ date --date="1/1/2016 12:00:00" +"%s"
1451649600
$ date --date="1/1/2028 12:00:00" +"%s"
1830340800
$ date --date="1/1/2028 12:00:01" +"%s"
1830340801

I see even if wp_next_scheduled() returned the correct timestamp the condition would fail and any other timestamp would be accepted.

<?php
        $next = wp_next_scheduled($hook, $args);
        if ( $next && abs( $next - $timestamp ) <= 10 * MINUTE_IN_SECONDS ) {
                return;
        }

$ php -r "echo abs( 1830340800 - time()) . \" < \". (10*60) . \" => \" . (int)(abs( 1830340800 - time()) < (10*60)) . \"\\n\";"
295308138 < 600 => 0
$ php -r "echo abs( 1830340801 - time()) . \" < \". (10*60) . \" => \" . (int)(abs( 1830340801 - time()) < (10*60)) . \"\\n\";"
295308096 < 600 => 0
Last edited 6 years ago by bodohugobarwich (previous) (diff)

#5 @bodohugobarwich
6 years ago

Therefore my proposition would be a Function wp_last_scheduled()
which would look for the biggest timestamp for a given hook

<?php
function wp_last_scheduled( $hook, $args = array() ) {
        $crons = _get_cron_array();
        $key = md5(serialize($args));
        $lasttimestamp = 0;
        if ( empty($crons) )
                return false;
        foreach ( $crons as $timestamp => $cron ) {
                if ( isset( $cron[$hook][$key] ) )
                       if ( $timestamp > $lasttimestamp )
                               $lasttimestamp = $timestamp;
        }

        if ( $lasttimestamp > 0 ) 
               return $lasttimestamp;
        else
               return false;
}

#6 @peterwilsoncc
6 years ago

Unfortunately such a check would reverse the problem rather than fix the bug. If multiple events are scheduled, a new event could be registered within ten minutes of all but the last event.

An accurate check would require looping through the cron array and comparing any events that fall within ten minutes of the event being scheduled. Something along the lines of:

<?php
foreach ( $crons as $timestamp => $cron ) {
        if ( /* the two timestamps are greater than ten minutes apart */ ) {
                continue;
        }
        if ( isset( $cron[ $hook ][ $key ] ) ) {
                // Prevent scheduling.
                return false;
        }
}

array_filter() can't be used to reduce the array as the $flag parameter is missing from older versions of PHP.

#7 @bodohugobarwich
6 years ago

Yes, it adds a restriction to the functionality that a new event must be at least 10 min after the last event.
So if you wanted to schedule events for the whole week you would schedule them from the first on Monday to the last on Sunday.

I found that many plugins and even the Wordpress Core with the do_ping task do rely on the restriction that too close scheduled events would be rejected therefore I could observe scheduled event of the same type in 1 second interval if they were not rejected.

I'm not aware where the 10 Minutes Limit does come from but redefining it reasonably would help to easy the confict.
Unix Systems do normally treat the scheduled events in 1 Minute Interval so that would be a useful Starting Point.

#8 follow-up: @peterwilsoncc
6 years ago

  • Keywords needs-patch added
  • Version changed from 4.9.8 to 2.7

I'm not aware where the 10 Minutes Limit does come from

It's arbitrary to try to prevent the cron array stored in the options table from becoming too large.

it adds a restriction to the functionality that a new event must be at least 10 min after the last event

For this ticket, I'd rather fix the problem of being able to schedule within ten minutes of any identical event (first, last or somewhere in between) using either a loop or other appropriate array function. The limit has been documented and assumed to be working since version 2.7.

@bodohugobarwich are you willing to work on a patch? You can use either Git or SVN to generate a patch and upload it to this ticket.

It's no problem if you don't have time, but it would be great to be able to give you your first props on your first ticket.

#9 in reply to: ↑ 8 @bodohugobarwich
6 years ago

For this ticket, I'd rather fix the problem of being able to schedule within ten minutes of any identical event (first, last or somewhere in between) using either a loop or other appropriate array function. The limit has been documented and assumed to be working since version 2.7.

@bodohugobarwich are you willing to work on a patch? You can use either Git or SVN to generate a patch and upload it to this ticket.

Yes, I would love to implement this Functionality for WordPress

Thinking about the issue and seeing that on a production blog in four years after its installation the Event Queue has grown up to 10000 queued pending events I noticed that the Event Queue is only indexed by the Event Time and it lacks a by Hook Index which would greatly improve the performance of the search operation.

#10 @SergeyBiryukov
6 years ago

  • Description modified (diff)

#11 follow-up: @bodohugobarwich
6 years ago

I implemented the Modification as discussed before in
src/wp-includes/cron.php
and added some new tests to check the functionality in
tests/phpunit/tests/cron.php
The PHPUnit test gave me green on all cron group tests

$ phpunit --debug --group cron
Starting test 'Tests_Cron::test_duplicate_past_event'.
.
Starting test 'Tests_Cron::test_not_duplicate_past_event'.
.
Starting test 'Tests_Cron::test_not_duplicate_past_event_reversed'.
OK (23 tests, 81 assertions)

I upload also a git-diff for you to check it.
I hope it is as you intended.

@bodohugobarwich
6 years ago

git-diff file of my local branch against the master on the files I modified

#12 @peterwilsoncc
6 years ago

  • Keywords has-patch has-unit-tests added; needs-patch removed
  • Owner set to peterwilsoncc
  • Status changed from new to assigned

#13 in reply to: ↑ 11 @peterwilsoncc
6 years ago

  • Keywords needs-refresh added
  • Milestone changed from Awaiting Review to 5.0

Replying to bodohugobarwich:

Thanks for the patch and, particularly, for including unit tests.

If the requested time stamp is less than ten minutes in the future, then $mintimestamp will need to be 0 as WP Cron spawns jobs for anything scheduled as time() or earlier.

To avoid nesting the isset check, I'd prefer to reverse the logic of ( $event_timestamp >= $mintimestamp && $event_timestamp <= $maxtimestamp ) and put a continue statement in there. This is a nit but nested logic can make reading the code a little more difficult.

For a few reasons, I'd prefer to keep the logic in wp_schedule_single_event() rather than in a new function:

  • it's only used on one place
  • WordPress version 5.0 will add a few filters to make custom cron runners simpler (such as Automattic's Cron Control and Human Made's Cavalcade); a new function will require another hook.

I've put this against the version 5.0 milestone as I think it's pretty much ready to go. I've also labelled it as needing a refresh, I can do this if you don't have time.

#14 @bodohugobarwich
6 years ago

I see your argument about creating a new function.

But about setting $mintimestamp to 0 this would make match $requested_timestamp against any already scheduled event lesser than $maxtimestamp
While the Requirement was that any event can be scheduled if there isn't any similar event already scheduled within 10 min of it.

That means that if there was already an event at -5 min an event at +6 min should be accepted, but an event at +3 min should be rejected.

I wrote two new test cases for this Use Case and they were checked ok:

$ phpunit --debug --group cron
Starting test 'Tests_Cron::test_duplicate_past_to_future_event'.
.
Starting test 'Tests_Cron::test_not_duplicate_past_to_future_event'.
.
OK (25 tests, 88 assertions)

@bodohugobarwich
6 years ago

git-diff of the new test cases of past events against future events

#15 @bodohugobarwich
6 years ago

About keeping the Logic within the function wp_schedule_single_event()
Do you want me to do the change or have you already written something that I would checkout?

#16 @peterwilsoncc
6 years ago

Do you want me to do the change or have you already written something that I would checkout?

I haven't written anything yet, if you have the time it would be great if you could refactor it.

But about setting $mintimestamp to 0 this would make match $requested_timestamp against any already scheduled event lesser than $maxtimestamp
While the Requirement was that any event can be scheduled if there isn't any similar event already scheduled within 10 min of it.

The loop that spawns cron jobs does so for any event with a time stamp between 0 and time().

The effect of this is that events scheduled at -30 min, -3 min and time() will all run at the same time. To avoid effectively scheduling single events to happen within ten minutes of another, the logic would be:

<?php

if ( $requested_timestamp < time() + 10 * MINUTE_IN_SECONDS ) {
  $mintimestamp = 0;
} else {
  $mintimestamp = $requested_timestamp - 10 * MINUTE_IN_SECONDS;
}

#17 follow-up: @bodohugobarwich
6 years ago

It's ok for me to do those changes.
I also can do the refresh with the upcoming 5.0 release branch.
Only I couldn't find it in the git Repository so I suppose it's the master branch.

#18 in reply to: ↑ 17 @peterwilsoncc
6 years ago

Replying to bodohugobarwich:

I also can do the refresh with the upcoming 5.0 release branch.
Only I couldn't find it in the git Repository so I suppose it's the master branch.

That's correct, we haven't created a branch for 5.0 so you can work from master.

Thanks.

#19 @bodohugobarwich
6 years ago

I updated my branch with the 5.0 branch, implemented the changes in /wp-includes/cron.php and deleted some tests about past evens which would apply into the same use case.
I upload the git-diff file of my branch to the 5.0 branch.

@bodohugobarwich
6 years ago

git-diff of my local branch to the 5.0 branch

@bodohugobarwich
6 years ago

git-diff of the correction of uncommited changes

#20 @peterwilsoncc
6 years ago

  • Milestone changed from 5.0 to 5.1

Moving to the 5.1 milestone due to the WordPress 5.0 focus on the new editor (Gutenberg).

#21 @bodohugobarwich
6 years ago

I understand.
Please, let me know when this development is going to be launched so I can do the update with the Release Branch when you like.

#22 @peterwilsoncc
6 years ago

  • Keywords 5-2-early added
  • Milestone changed from 5.1 to 5.2

@bodohugobarwich sorry, I missed this early on in 5.1; as we're late in the beta I will postpone this to 5.2-early.

A few more changes are going into cron.php for this release, once that's done I'll refresh the patch for you.

#23 @bodohugobarwich
6 years ago

Thank you, Yes. this is fine for me.

@peterwilsoncc
6 years ago

#24 @peterwilsoncc
6 years ago

44818.diff includes:

  • refresh existing patch against trunk
  • updates tests to use return values added in WP 5.1
  • improves logic for setting upper timestamp for determining the duplicate range
  • removes the empty() check in favor of ensuring $crons is always an array.

This ticket was mentioned in Slack in #core by peterwilsoncc. View the logs.


6 years ago

@peterwilsoncc
6 years ago

CS fix on previous patch.

#26 @peterwilsoncc
6 years ago

  • Resolution set to fixed
  • Status changed from assigned to closed

In 44917:

Cron: Ensure identical single events aren't scheduled less than 10min apart.

Improves the logic in wp_schedule_single_event() to ensure an identical event is not scheduled within ten minutes.

This moves the logic for checking for identical events to be self contained rather than relying on wp_next_scheduled() as this fails to account for events with a past timestamp when wp-cron fails to trigger or for multiple identical events being scheduled already.

Props bodohugobarwich.
Fixes #44818.

Note: See TracTickets for help on using tickets.