Make WordPress Core

Opened 6 months ago

Last modified 3 weeks ago

#57271 assigned defect (bug)

Cron unschedule / reschedule event errors

Reported by: domainsupport's profile domainsupport Owned by: audrasjb's profile audrasjb
Milestone: Awaiting Review Priority: normal
Severity: normal Version: 6.0
Component: Cron API Keywords: has-patch needs-unit-tests
Focuses: Cc:

Description

Multiple users have reported errors since v6.0 across installs with completely different themes and plugins ...

[09-Nov-2022 11:28:28 UTC] Cron unschedule event error for hook: do_pings, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {“schedule”:false,”args”:[]}

[09-Nov-2022 18:05:03 UTC] Cron unschedule event error for hook: wordfence_processAttackData, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {“schedule”:false,”args”:[]}

[21-Nov-2022 07:53:04 UTC] Cron reschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {“schedule”:”wf_scan_monitor_interval”,”args”:[],”interval”:60}

[21-Nov-2022 07:53:04 UTC] Cron unschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {“schedule”:”wf_scan_monitor_interval”,”args”:[],”interval”:60}

There are many more examples on the support thread https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/

I have so far been unable to find a way to manually re-produce this issue but this is what I have discovered so far ...

So this error happens when wp_unschedule_event() and wp_reschedule_event() fails.

could_not_set error is presented by _set_cron_array() which is the return function for wp_unschedule_event() and wp_schedule_event().

could_not_set error is returned by _set_cron_array() when the updating of the cron table fails with update_option( 'cron', $cron );.

update_option() fails when …

1) The $option parameter is empty
This should never happen
2) The old option value is the same as the new option value
This suggests the cron job is running more than once but may not be the only reason ... ?
3) The database insert query $wpdb->update() fails
This is a bit worrying but shouldn’t be the case as surely there should be an accompanying database error?

I think we can rule out (1) seeing as the $option parameter is never empty.

We can maybe rule out (2) because from the thread above, this happens on high traffic sites as well as low traffic sites and on sites using the default wp-cron firing as well as cron fired by the system … ?

The leaves (3) being the most likely cause of the "bug".

I have tried to assign to @audrasjb (I hope that's OK to do?) because they added the commit on the 20th September that started to highlight the issue https://github.com/WordPress/WordPress/commit/84d19848666a81584e0007a6ab7f7ad3c990d71a

I realise that this is not going to be easy to diagnose until the issue can be manually replicated but I think it should be looked into.

Oliver

Change History (29)

#1 @peterwilsoncc
6 months ago

I can see that wp_unschedule_event() may throw an error if the event being unscheduled is not set. Similarly wp_schedule_event() may throw the error if the event been scheduled is already set.

wp> wp_unschedule_event( time() - MONTH_IN_SECONDS, '57271cc', [], true );
=> class WP_Error#2637 (3) {
  public $errors =>
  array(1) {
    'could_not_set' =>
    array(1) {
      [0] =>
      string(39) "The cron event list could not be saved."
    }
  }
  public $error_data =>
  array(0) {
  }
  protected $additional_data =>
  array(0) {
  }
}

wp> $event_time = time() + MONTH_IN_SECONDS;
=> int(1672799267)
wp> wp_schedule_event( $event_time, 'weekly', '57271bcc', [], true );
=> bool(true)
wp> wp_schedule_event( $event_time, 'weekly', '57271bcc', [], true );
=> class WP_Error#2636 (3) {
  public $errors =>
  array(1) {
    'could_not_set' =>
    array(1) {
      [0] =>
      string(39) "The cron event list could not be saved."
    }
  }
  public $error_data =>
  array(0) {
  }
  protected $additional_data =>
  array(0) {
  }
}

I don't think these functions should return could_not_set in either of these circumstances. Whether the functions should return an error if called in this fashion is a discussion for elsewhere.

In both of these circumstances, the scenario being hit is number two in the original description: the options value already matches.

@domainsupport I noticed you mentioned in the support ticket you linked to that these events are not in your cron array, the leads me to suspect you are hitting these false error reports with wp_unschedule_event().

#3 @peterwilsoncc
6 months ago

  • Keywords needs-unit-tests added

I've linked a pull request to this issue to prevent the false could_not_set errors. It's in draft as it still needs some unit tests though.

#4 follow-up: @domainsupport
6 months ago

Thank you so much for taking a look at this.

Our site was (I say "was" because we've not had a PHP error notice about this for a few days now) showing errors for both "reschedule" and "unschedule". Other users in the support thread are still receiving multiple entries in their log files.

What you've explained sounds right ... BUT ... surely if events are attempting to unschedule when they don't exist and schedule when they do exist then this would suggest that the events are somehow running more than once (concurrently perhaps?) and have already unscheduled / rescheduled themselves?

If not then what else could cause this behaviour? And surely preventing the error for this scenario won't actually be resolving the root of the issue?

Thanks again.

#5 in reply to: ↑ 4 ; follow-ups: @peterwilsoncc
6 months ago

Replying to domainsupport:

What you've explained sounds right ... BUT ... surely if events are attempting to unschedule when they don't exist and schedule when they do exist then this would suggest that the events are somehow running more than once (concurrently perhaps?) and have already unscheduled / rescheduled themselves?

If not then what else could cause this behaviour? And surely preventing the error for this scenario won't actually be resolving the root of the issue?

My first thought was concurrency too, but I can't figure out the best way to test that idea.

The only other possible cause I could think of is if the event is been scheduled or unscheduled without plugins checking wp_next_scheduled() first. I did a quick scan of the plugin repository for the events recorded in the support ticket but couldn't see any likely causes initially.

Were you seeing the error in local or development enviroments?

#6 in reply to: ↑ 5 @tynanbe
6 months ago

Replying to peterwilsoncc:

Were you seeing the error in local or development enviroments?

Several LiteSpeed Cache users have reported similar issues happening on production sites, and it looks like they're not limited to plugins alone.

Error de evento de reprogramación de cron para el gancho: action_scheduler_run_queue. Código de error: could_not_set. Mensaje de error: No se ha podido guardar la lista de eventos del cron.. Datos: {"schedule":"every_minute","args":["WP Cron"],"interval":60}
Error de evento de anulación de programación de cron para el gancho: action_scheduler_run_queue. Código de error: could_not_set. Mensaje de error: No se ha podido guardar la lista de eventos del cron.. Datos: {"schedule":"every_minute","args":["WP Cron"],"interval":60}

#7 in reply to: ↑ 5 ; follow-up: @domainsupport
6 months ago

Replying to peterwilsoncc:

Were you seeing the error in local or development enviroments?

My experience is with a live site https://ryesussex.uk which receives about 15,000 unique visitors per month.

The following cron hooks ...

  • do_pings (I've personally seen this one)
  • wp_update_plugins
  • wp_privacy_delete_old_export_files
  • wp_version_check

... are all core hooks (I believe) and have all been seen in the support thread which rules out a plugin not using wp_next_scheduled() properly I believe?

One theory I had was concurrent requests to a WordPress installation from different hostnames (with and without "www." or with and without SSL for example, they don't have to be completely different domains) firing the same cron event?

In fact, if a site were visited via "http://" and WordPress then redirected to "https://" would these two requests (so close together) be able to fire the same cron event before it had completed and been removed from the schedule?

Oliver

#8 in reply to: ↑ 7 ; follow-up: @peterwilsoncc
6 months ago

Replying to domainsupport:

[snip]
... are all core hooks (I believe) and have all been seen in the support thread which rules out a plugin not using wp_next_scheduled() properly I believe?

Yes, that's correct. They are all core hooks.

One theory I had was concurrent requests to a WordPress installation from different hostnames (with and without "www." or with and without SSL for example, they don't have to be completely different domains) firing the same cron event?

In fact, if a site were visited via "http://" and WordPress then redirected to "https://" would these two requests (so close together) be able to fire the same cron event before it had completed and been removed from the schedule?

wp-cron.php sets a transient in order to prevent events running in this manner but this might be possible if the time between two requests is very quick or if the site is running a plugin that disable transients.

It's certainly something worth looking in to, thanks.

#9 in reply to: ↑ 8 ; follow-up: @domainsupport
6 months ago

Replying to peterwilsoncc:

One theory I had was concurrent requests to a WordPress installation from different hostnames (with and without "www." or with and without SSL for example, they don't have to be completely different domains) firing the same cron event?

wp-cron.php sets a transient in order to prevent events running in this manner but this might be possible if the time between two requests is very quick or if the site is running a plugin that disable transients.

I'd forgotten about this comment where he says he's not a high traffic site and his cron is set to run by the system so does that not rule out the concurrent request theory? https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/2/#post-16255896

#10 in reply to: ↑ 9 ; follow-up: @chargeup
6 months ago

Thinking out loud. If the cron job is set on the server for this domain http://domain.com/wp-cron.php?doing_wp_cron >/dev/null 2>&1 then redirects to https://www.domain.com/wp-cron.php?doing_wp_cron >/dev/null 2>&1 could that also cause a concurrent request? Just mentioning this as a possible cause in those cases for the concurrent request theory.

Replying to domainsupport:

Replying to peterwilsoncc:

One theory I had was concurrent requests to a WordPress installation from different hostnames (with and without "www." or with and without SSL for example, they don't have to be completely different domains) firing the same cron event?

wp-cron.php sets a transient in order to prevent events running in this manner but this might be possible if the time between two requests is very quick or if the site is running a plugin that disable transients.

I'd forgotten about this comment where he says he's not a high traffic site and his cron is set to run by the system so does that not rule out the concurrent request theory? https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/2/#post-16255896

#11 in reply to: ↑ 10 @domainsupport
6 months ago

Replying to chargeup:

Thinking out loud. If the cron job is set on the server for this domain http://domain.com/wp-cron.php?doing_wp_cron >/dev/null 2>&1 then redirects to https://www.domain.com/wp-cron.php?doing_wp_cron >/dev/null 2>&1 could that also cause a concurrent request? Just mentioning this as a possible cause in those cases for the concurrent request theory.

Looking at the way the transient is set in wp-cron.php with microtime() it would be almost impossible for the cron to be running concurrently as @peterwilsoncc says without the transient being disabled (which it isn't on our site). It would require two requests to fire at exactly the same microsecond (different hostname request wouldn't matter as the transient is stored in the database). The chances of this happening would be infinitesimally small and would not present the quantity of errors we are seeing.

It's an absolute mystery!

#12 @domainsupport
6 months ago

Having not had these errors in the logs for a while, they have made a re-appearance ...

[16-Dec-2022 06:48:13 UTC] Cron reschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"wf_scan_monitor_interval","args":[],"interval":60}
[16-Dec-2022 06:48:13 UTC] Cron unschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"wf_scan_monitor_interval","args":[],"interval":60}
[16-Dec-2022 06:48:15 UTC] Cron reschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"wf_scan_monitor_interval","args":[],"interval":60}

I think this is significant because I thought that the update of core itself could have been a cause but there hasn't been an update for a long time. Furthermore, the schedule for this hook is 1 minute and it's a custom schedule / hook. This means that whatever the cause is, it is independent of core / custom schedule and independent of core / custom hook.

#13 @courageous999
6 months ago

We're a live but not a high traffic site that has also started seeing this exact error since upgrading WordPress to v6.1.1. The errors started to appear sometime in November but I've been patiently ignoring them (since at the time I did not find any mention of it by anyone online).

I had the following custom CRON event set in my child theme's functions.php file:

wp_schedule_event(strtotime('10:00:00'), 'daily', 'ft_remove_stripe_cron');

This was throwing the following error in my error_log about 50 times a minute:

[20-Dec-2022 15:59:02 UTC] Cron reschedule event error for hook: ft_remove_stripe_cron, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"daily","args":[],"interval":86400}

After going through this ticket, I was finally able to find out that what I needed was the following:

if ( !wp_next_scheduled('ft_remove_stripe_cron') )
    wp_schedule_event(strtotime('10:00:00'), 'daily', 'ft_remove_stripe_cron');

Suffice to say that I have now had over 20 minutes of peace and quiet in my error_log since adding this!

Now my understanding is that my implementation was always wrong and was always failing to schedule an already set CRON event (but silently before). However, I find it intriguing (and perhaps of value to your investigation) that I was receiving that error 50 times a minute. I guarantee you that our site was not receiving 50 visits a minute! I highly doubt it even had 1 link clicked a minute.

Lastly, I should also mention that I've occasionally (amidst the barrage of repeated CRON event errors) seen other CRON events (not sure if set by a plugin or WordPress itself) also failing with this exact error.

EDIT:
By the way, if you're going to introduce a new error check, it would have immensely helped if you added some documentation with the update about it. On the 2nd day after this update, I searched your forums and Google for this exact error and found exactly zero results. Rather than wait a month and a half for a ticket addressing this, it would have saved me a lot of time and headache if there was some documentation regarding this new error check somewhere that simply points in the right direction to fixing it (my case was a fairly simple fix).

EDIT 2:
Just found these on a completely different site today:

[07-Jan-2023 12:54:56 UTC] Cron reschedule event error for hook: action_scheduler_run_queue, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"every_minute","args":["WP Cron"],"interval":60}
[07-Jan-2023 12:54:56 UTC] Cron reschedule event error for hook: wp_session_database_gc, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"hourly","args":[],"interval":3600}
Last edited 5 months ago by courageous999 (previous) (diff)

#14 @johnbillion
5 months ago

#57448 was marked as a duplicate.

#15 @AndyHenderson
4 months ago

FWIW, I've just seen this error in our log:

[01-Feb-2023 19:17:22 UTC] Cron unschedule event error for hook: backwpup_cron, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":false,"args":{"arg":"restart"}}

We implemented 6.1.1 shortly after release but have not seen the error until now. OTOH, we implemented PHP 8.1 from 7.4 yesterday. Coincidence? I hope I'm not setting a hare running.

Andy

#16 follow-up: @domainsupport
4 months ago

I've not seen the errors appear in our logs for some time now (although I'm under no illusion that the issue has resolved itself). However in all instances that we have seen this issue, it was with PHP 7.4 so @AndyHenderson I don't think that your PHP update to v8.1 was relevant.

Oliver

#17 in reply to: ↑ 16 ; follow-up: @j3gaming
3 months ago

Replying to domainsupport:

I've not seen the errors appear in our logs for some time now (although I'm under no illusion that the issue has resolved itself). However in all instances that we have seen this issue, it was with PHP 7.4 so @AndyHenderson I don't think that your PHP update to v8.1 was relevant.

Oliver

I'm still experiencing this and it's deleting my cron jobs. Are you saying the fix is to update PHP? Is there any code changes for this coming up in the next version of wordpress?

#18 in reply to: ↑ 17 @courageous999
3 months ago

Replying to j3gaming:

Replying to domainsupport:

I've not seen the errors appear in our logs for some time now (although I'm under no illusion that the issue has resolved itself). However in all instances that we have seen this issue, it was with PHP 7.4 so @AndyHenderson I don't think that your PHP update to v8.1 was relevant.

Oliver

I'm still experiencing this and it's deleting my cron jobs. Are you saying the fix is to update PHP? Is there any code changes for this coming up in the next version of wordpress?

We're currently running WordPres 6.1.1 and we updated to PHP 8.1 a little over a month ago and I'm still seeing errors like this in the logs about once a month (some of these are from plugins like Wordfence it seems):

[17-Feb-2023 15:24:47 UTC] Cron reschedule event error for hook: action_scheduler_run_queue, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"every_minute","args":["WP Cron"],"interval":60}
[08-Feb-2023 21:36:00 UTC] Cron reschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"wf_scan_monitor_interval","args":[],"interval":60}

So I can confirm that updating to PHP 8.1 will not resolve this issue.

Furthermore, I don't think that WordPress is officially ready for PHP 8.1 yet as our logs are filled with errors from the "wp-includes" folder in WordPress.

Last edited 3 months ago by courageous999 (previous) (diff)

#19 @domainsupport
3 months ago

@j3gaming No, I'm not saying updating PHP will solve your issue, I'm saying that updating PHP didn't cause the issue. There is still no fix for the issue as the cause has still not presented itself or been discovered.

#20 @j3gaming
3 months ago

I figured out how to trigger this 100% of the time, which also ends up deleting 1 or multiple cron tasks.

Environment:
Linux, with linux system crons running once a minute (crontab -e)
Webmin
PHP 7.4
Wordpress 6.1.1 (DISABLE_WP_CRON = true)

Within webmin, run a database backup. This usually takes ~5 minutes to complete for my website. Doing anything that would generally freeze/stop the website & database would probably work

During that time, the linux cron will run. The result is this error message and 1 or more cron jobs being deleted.

Log: https://dev.fillmore.mobi/wp-content/uploads/fillmore.error.log

Last edited 3 months ago by j3gaming (previous) (diff)

#21 @j3gaming
3 months ago

-deleted

Last edited 3 months ago by j3gaming (previous) (diff)

#22 @domainsupport
3 months ago

@peterwilsoncc I'm confident that I now know what's causing this.

After the comment from @j3gaming, I modified line 520 of /wp-includes/option.php as follows ...

<?php
        $result = $wpdb->update( $wpdb->options, $update_args, array( 'option_name' => $option ) );
        if ( ! $result ) {
if ('cron' === $option) { error_log('Cron failed to save to the database'); }
                return false;
        }

Then I waited for the next could_not_set error notice and sure enough ...

[05-Mar-2023 01:01:02 UTC] Cron failed to save to the database
[05-Mar-2023 01:01:02 UTC] Cron reschedule event error for hook: wf_scan_monitor, Error code: could_not_set, Error message: The cron event list could not be saved., Data: {"schedule":"wf_scan_monitor_interval","args":[],"interval":60}

So this confirms that the issue occurs when (for whatever reason) update_option() is unable to save to the database.

This makes me immediately ask two questions ...

  1. What mechanism exists whereby if $wpdb->update() fails in update_option(), the request is saved (maybe as .json to the file system) until such time as the issue with the database has been resolved and the $wpdb->update() failures can be re-run or does this need to be developed?
  2. What other update_option() failures are going un-recorded?!

If the answer to 2. is unknown then I think this ticket's severity needs to be upgraded to "major" because it would mean that swathes of update_option() requests could be (and probably are) going silently uncompleted if there is a glitch with the database.

Oliver

#24 follow-up: @galbaras
3 months ago

update_option() calls wpdb::update(), which doesn't check for errors, but it called wpdb::query(), which seems to be outputting messages when errors occur. However, it doesn't do this when the database connection is lost, in which case, I retries, and the dies if unsuccessful.

This may be our real culprit. See here.

Also, wpdb::check_connection() uses $this->reconnect_retries, which is set to 5 without a filter, and sleep(1), also without a filter in the sleep duration. So if the connection isn't restored in 5 seconds, it's game over, wheras in real life, restoring the connection can take a lot longer.

Changing these values arbitrarily could cause pages to stall for too long, but assuming this is a rare occurrence, or, as is the case with cron, waiting isn't an issue, this may not be such a bad idea.

In fact, checking again in 1 second, then 5 seconds, then 10 seconds, then 30 seconds, then 1 minute can help get a quick reconnection when possible, but still a reconnection when that takes longer. It's the sort of retry logic used in networking and other systems to increase reliability.

#25 in reply to: ↑ 24 @j3gaming
3 months ago

Replying to galbaras:

Does this logic re-fire a cron? This gets into a tricky situation where you're actually re-running a cron because of a database issue, but what if the cron is doing non-database related things, processing data or emailing people for example? You may not want the cron to be re-trying to fire for the next hour. Also, what if the cron is what's causing the connection issues.

Need to either be able to pick up from exactly where you left off, or if a cron hit a connection error, I wouldn't schedule it to try again asap. Just wait until it's regularly scheduled next. Or, maybe a user defined option for if a cron should retry if you get a database error.

Last edited 3 months ago by j3gaming (previous) (diff)

#26 @galbaras
3 months ago

Does this logic re-fire a cron?

No, it just (almost) ensures that settings are updated when they need to be, and the cron setting will be covered too.

You may not want the cron to be re-trying to fire for the next hour

It won't fire any differently. While the database connection is down, cron won't "know" what to do, but (nearly) as soon as it comes up, the cron setting will be updated, and the next run will do the right thing.

#27 @jbcouton
6 weeks ago

Hello @audrasjb,

To follow up on our discussion at WordCamp Paris about the CRON error
Here is the return of WP Rocket:
This CRON error about the preload process is not something that can be handled/caused by WP Rocket.
This cron error is related to WordPress itself. It seems that there is something in the latest version that is causing this error.

See this comment for reference: https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/2/#post-16255658

#28 follow-up: @Krstarica
3 weeks ago

Any update on this? This happens a lot on high traffic site.

#29 in reply to: ↑ 28 @domainsupport
3 weeks ago

Replying to Krstarica:

Any update on this? This happens a lot on high traffic site.

This is where I am with it https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/9/#post-16740674

Note: See TracTickets for help on using tickets.