Opened 17 months ago
Last modified 5 months ago
#57924 assigned defect (bug)
Cron fires twice
| Reported by: |
j3gaming
|
Owned by: |
j3gaming
|
|---|---|---|---|
| Milestone: | Awaiting Review | Priority: | normal |
| Severity: | critical | Version: | 6.1.1 |
| Component: | Cron API | Keywords: | changes-requested 2nd-opinion |
| Focuses: | Cc: |
Description
Problem:
In wp-includes/cron.php _set_cron_array( $cron, $wp_error = false ) is rarely called without every cron task in the $cron parameter. Eventually leading to a random one being deleted by update_option('cron', $cron);
Expected Behaviour:
(Assuming 22 total crons)
wp_schedule_event( ... ) runs.
Passing in a total count of 23 $crons into _set_cron_array( $crons, $wp_error );
(not sure why it's +1 the total cron count)
wp_unschedule_event( ... ) runs.
Passing in a total count of 22 $crons into _set_cron_array( $crons, $wp_error );
(I assume the one from the previous call is being removed)
Then the cron is executed. Ready for the next time.
The Bug:
RARELY, the incorrect amount is passed, causing a series of events, that deletes the cron entirely.
I am debugging this myself as I can make this happen regularly and will continue to log my progress here. I am hoping to fix this myself for the community, I'm also posting to see if anything has been flagged in the past to give me a head start.
Change History (24)
#1
@
17 months ago
- Summary changed from _set_cron_array called with incorrect crons to Cron Goes Missing. _set_cron_array called with incorrect number of crons
@
@
#4
@
17 months ago
Wild layman's guess: Perhaps some kind of race condition, where something gets scheduled between counting and executing?
#5
@
17 months ago
@j3gaming Is your cron still set by the system to fire every minute as you mention here? https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/6/#post-16503835
Also, have you resolved the issue with your database that you mention here? https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/6/#post-16526520
Firing cron every minute by the system (rather than waiting for a WordPress page load) should prevent a race condition I believe ... ?
But ... if your database connection is lost then cron events will fail to be re-scheduled (which is not the same as being deleted I don't think) as I mentioned here https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/6/#post-16526604
I like @galbaras hypothesis here https://core.trac.wordpress.org/ticket/57271#comment:24 and my gut is that this is what's causing your issue.
#6
@
17 months ago
@SergeyBiryukov Could be related, but each ticket has different outcomes. My ticket is to resolve crons being deleted. The other ticket is a spammed error log that is connected to some db updates that previously had silent failures.
@galbaras I'm able to reproduce it by running my database backup. The backup takes 3-5 minutes to complete, and causes my site to be in an intermittent state. Lots of dropped connections, and what users would describe as "lag". While running my backup, it is very comparable to what a DDOS would look like.
@tobifjellner I think that's incredibly close, or exactly what's happening.
@domainsupport Yes, my cron fires each minute. Even when I set it to fire every 10 minutes, I can still reproduce the issue, as long as that backup is running while a cron is set to run. Because I'm able to reproduce the issue by simply doing a backup, while a cron is set to run, the recurrence timing of the cron is not related in my opinion.
#7
@
17 months ago
Alright, I'll first show you the logging I added.
wp_schedule_event, right before the return statement. Just to backtrace the _set_cron_array caller.
wp_unschedule_event, right before the return statement. Just to backtrace the _set_cron_array caller.
_set_cron_array has a bit more complex logging. I'm using a magic number of 22, because I have 22 total crons. Anything less than your usual total cron count passed into this function, is what's deleting them.
3 functions with extra logging in cron.php:
function wp_schedule_event( $timestamp, $recurrence, $hook, $args = array(), $wp_error = false ) {
// Make sure timestamp is a positive integer.
if ( ! is_numeric( $timestamp ) || $timestamp <= 0 ) {
if ( $wp_error ) {
return new WP_Error(
'invalid_timestamp',
__( 'Event timestamp must be a valid Unix timestamp.' )
);
}
return false;
}
$schedules = wp_get_schedules();
if ( ! isset( $schedules[ $recurrence ] ) ) {
if ( $wp_error ) {
return new WP_Error(
'invalid_schedule',
__( 'Event schedule does not exist.' )
);
}
return false;
}
$event = (object) array(
'hook' => $hook,
'timestamp' => $timestamp,
'schedule' => $recurrence,
'args' => $args,
'interval' => $schedules[ $recurrence ]['interval'],
);
/** This filter is documented in wp-includes/cron.php */
$pre = apply_filters( 'pre_schedule_event', null, $event, $wp_error );
if ( null !== $pre ) {
if ( $wp_error && false === $pre ) {
return new WP_Error(
'pre_schedule_event_false',
__( 'A plugin prevented the event from being scheduled.' )
);
}
if ( ! $wp_error && is_wp_error( $pre ) ) {
return false;
}
return $pre;
}
/** This filter is documented in wp-includes/cron.php */
$event = apply_filters( 'schedule_event', $event );
// A plugin disallowed this event.
if ( ! $event ) {
if ( $wp_error ) {
return new WP_Error(
'schedule_event_false',
__( 'A plugin disallowed this event.' )
);
}
return false;
}
$key = md5( serialize( $event->args ) );
$crons = _get_cron_array();
$crons[ $event->timestamp ][ $event->hook ][ $key ] = array(
'schedule' => $event->schedule,
'args' => $event->args,
'interval' => $event->interval,
);
uksort( $crons, 'strnatcasecmp' );
error_log("wp_schedule_event");
return _set_cron_array( $crons, $wp_error );
}
function wp_unschedule_event( $timestamp, $hook, $args = array(), $wp_error = false ) {
// Make sure timestamp is a positive integer.
if ( ! is_numeric( $timestamp ) || $timestamp <= 0 ) {
if ( $wp_error ) {
return new WP_Error(
'invalid_timestamp',
__( 'Event timestamp must be a valid Unix timestamp.' )
);
}
return false;
}
/**
* Filter to preflight or hijack unscheduling of events.
*
* Returning a non-null value will short-circuit the normal unscheduling
* process, causing the function to return the filtered value instead.
*
* For plugins replacing wp-cron, return true if the event was successfully
* unscheduled, false or a WP_Error if not.
*
* @since 5.1.0
* @since 5.7.0 The `$wp_error` parameter was added, and a `WP_Error` object can now be returned.
*
* @param null|bool|WP_Error $pre Value to return instead. Default null to continue unscheduling the event.
* @param int $timestamp Timestamp for when to run the event.
* @param string $hook Action hook, the execution of which will be unscheduled.
* @param array $args Arguments to pass to the hook's callback function.
* @param bool $wp_error Whether to return a WP_Error on failure.
*/
$pre = apply_filters( 'pre_unschedule_event', null, $timestamp, $hook, $args, $wp_error );
if ( null !== $pre ) {
if ( $wp_error && false === $pre ) {
return new WP_Error(
'pre_unschedule_event_false',
__( 'A plugin prevented the event from being unscheduled.' )
);
}
if ( ! $wp_error && is_wp_error( $pre ) ) {
return false;
}
return $pre;
}
$crons = _get_cron_array();
$key = md5( serialize( $args ) );
unset( $crons[ $timestamp ][ $hook ][ $key ] );
if ( empty( $crons[ $timestamp ][ $hook ] ) ) {
unset( $crons[ $timestamp ][ $hook ] );
}
if ( empty( $crons[ $timestamp ] ) ) {
unset( $crons[ $timestamp ] );
}
error_log("wp_unschedule_event");
return _set_cron_array( $crons, $wp_error );
}
function _set_cron_array( $cron, $wp_error = false ) {
if ( ! is_array( $cron ) ) {
$cron = array();
}
$cron['version'] = 2;
$checking = get_option('cron');
error_log('count(get_option(cron)): ' . count($checking) . '). count(cron): ' . count($cron));
//$debug = 'Current $cron: ' . print_r(get_option('cron'), true) . '\n';
//$debug .= 'Trying to save: (array count: ' . count($cron) . ') ' . print_r($cron, true) . '\n';
$result = false;
if (count($cron) >= 22)
{
$result = update_option( 'cron', $cron );
}
else
{
error_log("Cron array count is: " . count($cron) . " " . var_export($cron, true));
}
if ( $wp_error && ! $result ) {
return new WP_Error(
'could_not_set',
__( 'The cron event list could not be saved. ' . var_export($wp_error, true) . ' ' . var_export($result, true))
);
}
return $result;
}
Finally, I have logging inside a cron that fires. First line, and last line.
error_log("[" . time() . "] Started email_send");
// Basically...
// database pull if (sent == 0) from a custom table
// for (all unsent emails)
// wp_mail()
// wpdb->update(sent = 1)
// ... more code ...
error_log("[" . time() . "] Ended email_send");
Here is the log that happens 99.99% of the time. Perfect flow of code as intended and expected.
[15-Mar-2023 07:40:01 UTC] wp_schedule_event [15-Mar-2023 07:40:01 UTC] count(get_option(cron)): 22). count(cron): 23 [15-Mar-2023 07:40:01 UTC] wp_unschedule_event [15-Mar-2023 07:40:01 UTC] count(get_option(cron)): 23). count(cron): 22 [15-Mar-2023 07:40:01 UTC] [1678866001] Started email_send [15-Mar-2023 07:40:01 UTC] [1678866001] Ended email_send
The "extra" cron count (Being 23, 1 more than my total) is a bit weird to me, but seems to be intended. I'm guessing the cron needing to be run becomes the +1.
Here is what happens when the issue happens, padded with the "normal" logs above and below. Conveniently, this does produce the same logs (crontrol_cron_job Error code: could_not_set) being looked into in ticket #57271.
[15-Mar-2023 07:53:01 UTC] wp_schedule_event
[15-Mar-2023 07:53:01 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:53:01 UTC] wp_unschedule_event
[15-Mar-2023 07:53:01 UTC] count(get_option(cron)): 23). count(cron): 22
[15-Mar-2023 07:53:01 UTC] [1678866781] Started email_send
[15-Mar-2023 07:53:01 UTC] [1678866781] Ended email_send
[15-Mar-2023 07:54:01 UTC] wp_schedule_event
[15-Mar-2023 07:54:01 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:54:01 UTC] wp_unschedule_event
[15-Mar-2023 07:54:01 UTC] count(get_option(cron)): 23). count(cron): 22
[15-Mar-2023 07:54:01 UTC] [1678866841] Started email_send
[15-Mar-2023 07:54:01 UTC] [1678866841] Ended email_send
[15-Mar-2023 07:55:01 UTC] wp_schedule_event
[15-Mar-2023 07:55:01 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:55:01 UTC] wp_schedule_event
[15-Mar-2023 07:55:01 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:55:01 UTC] wp_unschedule_event
[15-Mar-2023 07:55:01 UTC] count(get_option(cron)): 23). count(cron): 22
[15-Mar-2023 07:55:01 UTC] [1678866901] Started email_send
[15-Mar-2023 07:55:02 UTC] [1678866902] Ended email_send
[15-Mar-2023 07:55:02 UTC] Cron reschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[15-Mar-2023 07:55:02 UTC] wp_unschedule_event
[15-Mar-2023 07:55:02 UTC] count(get_option(cron)): 22). count(cron): 21
[15-Mar-2023 07:55:02 UTC] Cron array count is: 21 array (
1678866965 =>
array (
'crontrol_cron_job' =>
array (
'c5a124df7ffc768428c29928207bd5ea' =>
array (
'schedule' => 'every10minutes',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/email_create.php\');',
'name' => 'Visit Pages, create emails',
),
'interval' => 600,
),
),
),
1678867861 =>
array (
'wp_privacy_delete_old_export_files' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'hourly',
'args' =>
array (
),
'interval' => 3600,
),
),
),
1678869928 =>
array (
'crontrol_cron_job' =>
array (
'bb9f4f2851baacef069c58263db7ece0' =>
array (
'schedule' => 'hourly',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/timesheet_data.php\');',
'name' => 'Process Timesheet Data',
),
'interval' => 3600,
),
),
),
1678870252 =>
array (
'crontrol_cron_job' =>
array (
'0e38b5f00429375214e3724e7bd79667' =>
array (
'schedule' => 'hourly',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/ha_data.php\');',
'name' => 'Process HA Data',
),
'interval' => 3600,
),
),
),
1678877358 =>
array (
'wp_https_detection' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
),
1678883400 =>
array (
'crontrol_cron_job' =>
array (
'dbf8b89544bd37e9d4df248597362f45' =>
array (
'schedule' => 'daily',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/missing_ha.php\');',
'name' => 'Missing HA with Timesheet',
),
'interval' => 86400,
),
),
),
1678892976 =>
array (
'wp_update_themes' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
'wp_version_check' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
),
1678892990 =>
array (
'delete_expired_transients' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'daily',
'args' =>
array (
),
'interval' => 86400,
),
),
),
1678893010 =>
array (
'updraftplus_clean_temporary_files' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
),
1678893062 =>
array (
'wp_update_plugins' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
),
1678893904 =>
array (
'recovery_mode_clean_expired_keys' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'daily',
'args' =>
array (
),
'interval' => 86400,
),
),
),
1678896028 =>
array (
'wp_scheduled_delete' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'daily',
'args' =>
array (
),
'interval' => 86400,
),
),
),
1678897179 =>
array (
'wp_scheduled_auto_draft_delete' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'daily',
'args' =>
array (
),
'interval' => 86400,
),
),
),
1678901178 =>
array (
'wp_update_user_counts' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'twicedaily',
'args' =>
array (
),
'interval' => 43200,
),
),
),
1678935600 =>
array (
'crontrol_cron_job' =>
array (
'63da9588156a987fc2e96975691b9427' =>
array (
'schedule' => 'daily',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/expense_pdf.php\');',
'name' => 'Generate Expense PDFs',
),
'interval' => 86400,
),
),
),
1678950000 =>
array (
'crontrol_cron_job' =>
array (
'f300f7f2a16d40298c6a47e56fe4743f' =>
array (
'schedule' => 'daily',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/ha_analysis.php\');',
'name' => 'HA Analysis',
),
'interval' => 86400,
),
),
),
1678950001 =>
array (
'crontrol_cron_job' =>
array (
'520211849dc3302397985c098960f252' =>
array (
'schedule' => 'daily',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/dailylogs.php\');',
'name' => 'Daily Logs',
),
'interval' => 86400,
),
),
),
1679080880 =>
array (
'wp_site_health_scheduled_check' =>
array (
'40cd750bba9870f18aada2478b24840a' =>
array (
'schedule' => 'weekly',
'args' =>
array (
),
'interval' => 604800,
),
),
),
1679317200 =>
array (
'crontrol_cron_job' =>
array (
'ae9e5f83cd3bc516206598c5e13f24d8' =>
array (
'schedule' => 'weekly',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/end_of_week_email.php\');',
'name' => 'End of Week Emails',
),
'interval' => 604800,
),
),
),
1679402700 =>
array (
'crontrol_cron_job' =>
array (
'8258fef7e673779075aa8570e56f905c' =>
array (
'schedule' => 'weekly',
'args' =>
array (
'code' => 'require_once(\'wp-content/cron/timesheet_approvals.php\');',
'name' => 'Timesheet Approval Reminder',
),
'interval' => 604800,
),
),
),
'version' => 2,
)
[15-Mar-2023 07:55:02 UTC] Cron unschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[15-Mar-2023 07:55:02 UTC] [1678866902] Started email_send
[15-Mar-2023 07:55:02 UTC] [1678866902] Ended email_send
[15-Mar-2023 07:56:02 UTC] wp_schedule_event
[15-Mar-2023 07:56:02 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:56:02 UTC] wp_unschedule_event
[15-Mar-2023 07:56:02 UTC] count(get_option(cron)): 23). count(cron): 22
[15-Mar-2023 07:56:02 UTC] [1678866962] Started email_send
[15-Mar-2023 07:56:02 UTC] [1678866962] Ended email_send
[15-Mar-2023 07:57:02 UTC] wp_schedule_event
[15-Mar-2023 07:57:02 UTC] count(get_option(cron)): 22). count(cron): 23
[15-Mar-2023 07:57:02 UTC] wp_unschedule_event
[15-Mar-2023 07:57:02 UTC] count(get_option(cron)): 23). count(cron): 22
[15-Mar-2023 07:57:02 UTC] [1678867022] Started email_create
[15-Mar-2023 07:57:02 UTC] [1678867022] Ended email_create
Missed it?
wp_schedule_event fires twice in a row, before the unschedule (which also fires twice in a row after). It is my opinion this is the root problem.
Then you get the crontrol_cron_job, Error code: could_not_set
Then, in apparently only my case, a cron would be deleted. I have thought about why only I'm seeing this.
This is possibly due to the fact I don't use functions.php to add a cron event, I used a plug-in for a one-off add. In installations where it's simply checking to add crons each time functions.php is run, the cron is re-added after being deleted, hiding the fact it was ever deleted.
#8
@
17 months ago
I changed the wp_schedule_event logging a bit.
~line 311
error_log("wp_schedule_event(" . var_export($timestamp, true) . ", " . var_export($recurrence, true) . ", " . var_export($hook, true) . ", ... , .... )");
return _set_cron_array( $crons, $wp_error );
That way I can see where the overlapping schedule events are coming from before it hits the error.
For example, I'm now getting:
[15-Mar-2023 22:37:01 UTC] wp_schedule_event(1678920365, 'every10minutes', 'crontrol_cron_job', ... , .... ) [15-Mar-2023 22:37:01 UTC] count(get_option(cron)): 22). count(cron): 23 [15-Mar-2023 22:37:01 UTC] wp_unschedule_event [15-Mar-2023 22:37:01 UTC] count(get_option(cron)): 23). count(cron): 22 [15-Mar-2023 22:37:01 UTC] [1678919821] Started email_create [15-Mar-2023 22:37:01 UTC] [1678919821] Ended email_create [15-Mar-2023 22:37:01 UTC] wp_schedule_event(1678919852, 'minutely', 'crontrol_cron_job', ... , .... ) [15-Mar-2023 22:37:01 UTC] count(get_option(cron)): 22). count(cron): 23 [15-Mar-2023 22:37:01 UTC] wp_unschedule_event [15-Mar-2023 22:37:01 UTC] count(get_option(cron)): 23). count(cron): 22 [15-Mar-2023 22:37:01 UTC] [1678919821] Started email_send [15-Mar-2023 22:37:01 UTC] [1678919821] Ended email_send
These 2 events firing on the same second, in the same cron run went fine and completed as expected.
#9
follow-up:
↓ 10
@
17 months ago
@j3gaming Are your database tables MyISAM or InnoDB? I'm going to go out on a limb and guess you are running MyISAM. MyISAM uses table-level locking, which means that if one query is modifying a table, another query cannot modify the same table until the first query has completed. This can result in locking issues and conflicts, especially when many concurrent queries are accessing the same table.
InnoDB is the default and most commonly used table engine in MySQL, and it provides good support for locking and concurrency, which can prevent conflicts and enable multiple queries to run simultaneously. InnoDB uses row-level locking and supports multiple concurrent transactions, which can help to prevent locking issues during INSERT/UPDATE queries.
Apologies if you are already running InnoDB however.
My earlier point, and one which I'm not 100% sure you are getting, is that if the database is locked up (whilst your backup is running, for example) it would appear that your site isn't able to run UPDATE/INSERT queries.
In this instance, the cron option cannot be saved which means that your cron events cannot be rescheduled and will appear that they have been deleted. They haven't, they've run, and then not been able to be saved in the database to run again.
You are correct that (in our case) we do not see evidence of our cron jobs not being re-scheduled ("deleted" as you say but that's not what's happening, the job has run so a new job has to be scheduled and that fails) because our application checks for the existence of the schedule and adds it if it doesn't exist (in a custom plugin, not functions.php) ...
if ( !wp_next_scheduled('my_cron_nightly') ) {
wp_schedule_event( strtotime('06:00:00 Europe/London'), 'daily', 'my_cron_nightly' );
}
Whilst this is an irritating problem when it happens sporadically on sites (as with the could_not_set issue) the missing schedule is picked up quickly and added again; when your cron jobs are set to run every minute and your database backup (which locks the database) runs for several minutes, it's going to be much more prevalent and 100% likely to occur and 100% likely that schedules are not added as required.
It is possible to change your database tables to use InnoDB instead of MyISAM, we do it all the time for our clients. Make sure you have a backup though! :)
That may be the solution to your problem ... although running cron every minute is still not a good idea. In my opinion.
Oliver
#10
in reply to:
↑ 9
@
17 months ago
Replying to domainsupport:
@j3gaming Are your database tables MyISAM or InnoDB? I'm going to go out on a limb and guess you are running MyISAM. MyISAM uses table-level locking, which means that if one query is modifying a table, another query cannot modify the same table until the first query has completed. This can result in locking issues and conflicts, especially when many concurrent queries are accessing the same table.
InnoDB is the default and most commonly used table engine in MySQL, and it provides good support for locking and concurrency, which can prevent conflicts and enable multiple queries to run simultaneously. InnoDB uses row-level locking and supports multiple concurrent transactions, which can help to prevent locking issues during INSERT/UPDATE queries.
Apologies if you are already running InnoDB however.
Just looked, every table is running InnoDB
My earlier point, and one which I'm not 100% sure you are getting, is that if the database is locked up (whilst your backup is running, for example) it would appear that your site isn't able to run UPDATE/INSERT queries.
In this instance, the cron option cannot be saved which means that your cron events cannot be rescheduled and will appear that they have been deleted. They haven't, they've run, and then not been able to be saved in the database to run again.
You are correct that (in our case) we do not see evidence of our cron jobs not being re-scheduled ("deleted" as you say but that's not what's happening, the job has run so a new job has to be scheduled and that fails) because our application checks for the existence of the schedule and adds it if it doesn't exist (in a custom plugin, not
functions.php) ...
if ( !wp_next_scheduled('my_cron_nightly') ) { wp_schedule_event( strtotime('06:00:00 Europe/London'), 'daily', 'my_cron_nightly' ); }Whilst this is an irritating problem when it happens sporadically on sites (as with the
could_not_setissue) the missing schedule is picked up quickly and added again; when your cron jobs are set to run every minute and your database backup (which locks the database) runs for several minutes, it's going to be much more prevalent and 100% likely to occur and 100% likely that schedules are not added as required.
Yes, it looks like I need to have the crons added via code. That way if they are ever missing from the crons option, they are immediately re-added. I think this type of code has been covering up this problem for a long time. Using a plug-in to add/remove crons (like WP Control), or anything that only one-off adds the cron, is the only way to experience them being deleted.
Can you do a test for me? Install WP Control and add a cron to it. Next time you get a could_not_set, can you see if it's still there?
That may be the solution to your problem ... although running cron every minute is still not a good idea. In my opinion.
It's a cron for sending emails, so I would like them to be delivered in a timely manner!
#11
@
17 months ago
I can confirm my issue is related to #57271
When ticket #57271 gets fixed. It's highly likely mine will be fixed too.
I added some logging within update_option. With @domainsupport's help this was added:
$wpdb->show_errors();
$result = $wpdb->update( $wpdb->options, $update_args, array( 'option_name' => $option ) );
if ( ! $result ) {
if ( 'cron' === $option ) {
error_log('Failed to save option "' . $option . '" to the wp_options table with value: ' . print_r($value, true) . ' (' . gettype($value) . ') and old value: ' . print_r($old_value, true) . ' (' . gettype($old_value) . ') and error: ' . $wpdb->last_error);
$wpdb->print_error();
}
return false;
}
Here is a summary of what the logs say when I have the problem.
I cut some out since it dumps the entire 22 count array, and is quite long. If you want the full log see:
https://wordpress.org/support/topic/cron-unschedule-event-error-for-hook/page/8/#post-16566622
[16-Mar-2023 06:55:01 UTC] wp_schedule_event(1678949732, 'minutely', 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 06:55:01 UTC] count(get_option(cron)): 22). count(cron): 23
[16-Mar-2023 06:55:01 UTC] wp_schedule_event(1678949732, 'minutely', 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 06:55:01 UTC] count(get_option(cron)): 22). count(cron): 23
[16-Mar-2023 06:55:01 UTC] wp_unschedule_event(1678949672, 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 06:55:01 UTC] count(get_option(cron)): 23). count(cron): 22
Failed to save option "cron" to the wp_options table
[16-Mar-2023 06:55:01 UTC] WordPress database error for query UPDATE `wp_dev_options` SET `option_value` =
[16-Mar-2023 06:55:01 UTC] Cron reschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved.
[16-Mar-2023 06:55:01 UTC] wp_unschedule_event(1678949672, 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 06:55:01 UTC] count(get_option(cron)): 22). count(cron): 21
[16-Mar-2023 06:55:01 UTC] Cron array count is: 21 array ( ... bunch of log spam and output of the 21 array values ... )
[16-Mar-2023 06:55:01 UTC] Cron unschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[16-Mar-2023 06:55:01 UTC] [1678949702] Started email_send
[16-Mar-2023 06:55:01 UTC] [1678949702] Started email_send
[16-Mar-2023 06:55:02 UTC] [1678949702] Ended email_send
[16-Mar-2023 06:55:02 UTC] [1678949702] Ended email_send
wp_schedule_event runs twice in a row.
wp_unschedule_event runs, and tries to _set_cron_array
Database error on wpdb->update failing to save.
wp_unschedule_event runs again
One of my crons will be deleted
Lots of plugins, and core wordpress crons, will have crons be re-added to the database. Any custom crons, like those added via WP Control will not be re-added.
Cron runs twice
#12
@
17 months ago
Question....
wp-cron.php
/*
* The cron lock (a unix timestamp set when the cron was spawned),
* must match $doing_wp_cron (the "key").
*/
if ( $doing_cron_transient !== $doing_wp_cron ) {
return;
}
If another cron is called on exactly the same timestamp (for whatever reason) would it bypass the lock? It looks like it would.
From what I can tell, if anyone visits /wp-cron.php?doing_wp_cron at the same moment Linux (or any OS) is doing a system level (real) cron... wouldn't that execute everything twice?
Is there a cleaner way to do this lock?
#13
@
17 months ago
- Summary changed from Cron Goes Missing. _set_cron_array called with incorrect number of crons to Cron fires twice
At this point I'm just using the ticket as a chronicle of my journey until I give up.
Hope the spam is fine!
I set some more logging. wp-cron.php this time:
/*
* The cron lock (a unix timestamp set when the cron was spawned),
* must match $doing_wp_cron (the "key").
*/
if ( $doing_cron_transient !== $doing_wp_cron ) {
return;
}
error_log(" START --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ");
error_log("[wp-cron.php] Jobs ready: " . count($crons) . ", with UNIX key: " . var_export($doing_cron_transient, true));
foreach ( $crons as $timestamp => $cronhooks ) {
...
// ... all the usual normal WP code ...
...
if ( _get_cron_lock() === $doing_wp_cron ) {
delete_transient( 'doing_cron' );
}
error_log(" --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- END");
die();
You would expect to NEVER get 2 "starts" in a row right?
It's possible. Notice the different $doing_cron_transient outputs? The microtime(true) is slightly different. At the end of the log, I do get double the outputs from my code inside the cron.
[16-Mar-2023 22:05:01 UTC] START --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
[16-Mar-2023 22:05:01 UTC] [wp-cron.php] Jobs ready: 1, with UNIX key: '1679004301.2089200019836425781250'
[16-Mar-2023 22:05:01 UTC] wp_schedule_event(1679004332, 'minutely', 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 22:05:01 UTC] START --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
[16-Mar-2023 22:05:01 UTC] [wp-cron.php] Jobs ready: 1, with UNIX key: '1679004301.2094271183013916015625'
[16-Mar-2023 22:05:01 UTC] wp_schedule_event(1679004332, 'minutely', 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 22:05:01 UTC] wp_unschedule_event(1679004272, 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 22:05:01 UTC] Cron reschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[16-Mar-2023 22:05:01 UTC] wp_unschedule_event(1679004272, 'crontrol_cron_job', array (
'code' => 'require_once(\'wp-content/cron/email_send.php\');',
'name' => 'Send Emails',
) , .... )
[16-Mar-2023 22:05:01 UTC] Cron unschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[16-Mar-2023 22:05:01 UTC] [1679004301] Started email_send
[16-Mar-2023 22:05:01 UTC] [1679004301] Started email_send
[16-Mar-2023 22:05:01 UTC] [1679004301] Ended email_send
[16-Mar-2023 22:05:01 UTC] [1679004301] Ended email_send
[16-Mar-2023 22:05:01 UTC] --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- END
When The cron gets past the lock, firing twice I can trigger could_not_set.
Proposed fix: Better locking to ensure it only runs once.
Not sure if I can help further. I'm unsure how this would change to ensure the lock is properly coded & checked.
Maybe something like a sleep for 1 second, and re-check the lock? Only the first or last to get there gets to execute the cron?
#14
@
17 months ago
This comment may help: https://core.trac.wordpress.org/ticket/57271#comment:11
Specifically:
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 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.
#15
follow-up:
↓ 21
@
17 months ago
- Keywords changes-requested 2nd-opinion added
It's not the same microsecond, and it doesn't have to be.
I recorded the $doing_cron_transient variable.
My cron is triggered twice, in just the same second. With different microtimes.
Here are the logs:
[17-Mar-2023 00:40:01 UTC] ['1679013601.6444039344787597656250'] START --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
[17-Mar-2023 00:40:01 UTC] ['1679013601.6444039344787597656250'] Jobs ready: 1
[17-Mar-2023 00:40:01 UTC] ['1679013601.6447730064392089843750'] START --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
[17-Mar-2023 00:40:01 UTC] ['1679013601.6447730064392089843750'] Jobs ready: 1
[17-Mar-2023 00:40:01 UTC] Cron reschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[17-Mar-2023 00:40:01 UTC] Cron unschedule event error for hook: crontrol_cron_job, Error code: could_not_set, Error message: The cron event list could not be saved. true false, Data: {"schedule":"minutely","args":{"code":"require_once('wp-content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
[17-Mar-2023 00:40:01 UTC] Started email_send
[17-Mar-2023 00:40:01 UTC] Started email_send
[17-Mar-2023 00:40:01 UTC] Ended email_send
[17-Mar-2023 00:40:01 UTC] Ended email_send
[17-Mar-2023 00:40:01 UTC] ['1679013601.6447730064392089843750'] --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- END
Job # 1679013601.6444039344787597656250
and
Job # 1679013601.6447730064392089843750
Starts at nearly the same time. Notice it's not exactly the same. It's quick enough that both are set before either script can check if something is set.
Notice how I only have 1 "end"? That's because of this code near the bottom of the loop:
// If the hook ran too long and another cron process stole the lock, quit.
if ( _get_cron_lock() !== $doing_wp_cron ) {
return;
}
The bottom of the loop detected that there was 2 running. It quit one of them (after executing 1 job twice). The one that quit, was the unix microtime that was not in the database. The one that made it into the database gets to continue.
My ATTEMPTED fix [THAT DID NOT WORK]. wp-config.php
// The cron lock: a unix timestamp from when the cron was spawned.
$doing_cron_transient = get_transient( 'doing_cron' );
// Use global $doing_wp_cron lock, otherwise use the GET lock. If no lock, try to grab a new lock.
if ( empty( $doing_wp_cron ) ) {
if ( empty( $_GET['doing_wp_cron'] ) ) {
// Called from external script/job. Try setting a lock.
if ( $doing_cron_transient && ( $doing_cron_transient + WP_CRON_LOCK_TIMEOUT > $gmt_time ) ) {
return;
}
$doing_wp_cron = sprintf( '%.22F', microtime( true ) );
$doing_cron_transient = $doing_wp_cron;
set_transient( 'doing_cron', $doing_wp_cron );
} else {
$doing_wp_cron = $_GET['doing_wp_cron'];
}
}
// Wait x seconds before checking the database.
sleep(2); // Could be WP_CONFIG configurable. Default could be 0, anyone complaining about crons running could set this to 1 or more.
// Grab the true database value after possible racing conditions.
$doing_cron_transient = get_transient( 'doing_cron' );
/*
* The cron lock (a unix timestamp set when the cron was spawned),
* must match $doing_wp_cron (the "key").
*/
if ( $doing_cron_transient !== $doing_wp_cron ) {
return;
}
#16
follow-up:
↓ 17
@
17 months ago
@j3gaming Quick question ... how is it possible for your cron to be firing twice at the (almost) exact same time if you are using the system to fire cron once per minute? How exactly have you setup your system to fire cron? Thanks.
#17
in reply to:
↑ 16
;
follow-up:
↓ 24
@
17 months ago
Replying to domainsupport:
@j3gaming Quick question ... how is it possible for your cron to be firing twice at the (almost) exact same time if you are using the system to fire cron once per minute? How exactly have you setup your system to fire cron? Thanks.
Not 100% sure, I have guesses though.
My environment is Linux, using crontab -e
Here is the line in /var/spool/cron/crontabs/username
* * * * * wget -q -O - "https://DOMAIN.COM/wp-cron.php?doing_wp_cron" >/dev/null 2>&1
I'm guess this mimics a web request to wp-cron.php?doing_wp_cron
If search engine bots (or anything) visited wp-cron.php?doing_wp_cron
wouldn't both trigger?
#18
follow-up:
↓ 19
@
17 months ago
Stupid question that I have to ask, you do have define('DISABLE_WP_CRON', true) in wp-config.php, right?
I don't use server fired cron so cannot comment on what third party requests might do but you could add this to .htaccess (if Apache) to prevent them ... ?
RewriteCond %{REMOTE_ADDR} !^127\.0\.0\.1
RewriteCond %{REQUEST_URI} "^/wp-cron.php"
RewriteRule .* - [L]
#19
in reply to:
↑ 18
@
17 months ago
Replying to domainsupport:
Stupid question that I have to ask, you do have
define('DISABLE_WP_CRON', true)inwp-config.php, right?
I don't use server fired cron so cannot comment on what third party requests might do but you could add this to
.htaccess(if Apache) to prevent them ... ?
RewriteCond %{REMOTE_ADDR} !^127\.0\.0\.1 RewriteCond %{REQUEST_URI} "^/wp-cron.php" RewriteRule .* - [L]
I do have DISABLE_WP_CRON set to true. Not sure I have htaccess on this host. This is my first time using linux ever, so bare with me. Do you think the rules will make a difference? Any thought on a bug within linux firing the cron twice?
#20
@
17 months ago
I've not tested those rules but that's how I would block third party access to /wp-cron.php if I was running an Apache server. For Nginx I believe you edit the configuration file and add ...
location ~ ^/wp-cron.php {
allow 127.0.0.1;
deny all;
}
Preventing all but the local machine from being able to access wp-cron.php would affirm that the issue is with the way you're firing cron. That's where my expertise ends though as I don't use the OS to fire cron on any of our sites so cannot provide any insight, sorry.
#21
in reply to:
↑ 15
@
17 months ago
Replying to j3gaming:
My fix. wp-config.php
// The cron lock: a unix timestamp from when the cron was spawned. $doing_cron_transient = get_transient( 'doing_cron' ); // Use global $doing_wp_cron lock, otherwise use the GET lock. If no lock, try to grab a new lock. if ( empty( $doing_wp_cron ) ) { if ( empty( $_GET['doing_wp_cron'] ) ) { // Called from external script/job. Try setting a lock. if ( $doing_cron_transient && ( $doing_cron_transient + WP_CRON_LOCK_TIMEOUT > $gmt_time ) ) { return; } $doing_wp_cron = sprintf( '%.22F', microtime( true ) ); $doing_cron_transient = $doing_wp_cron; set_transient( 'doing_cron', $doing_wp_cron ); } else { $doing_wp_cron = $_GET['doing_wp_cron']; } } // Wait x seconds before checking the database. sleep(2); // Could be WP_CONFIG configurable. Default could be 0, anyone complaining about crons running could set this to 1 or more. // Grab the true database value after possible racing conditions. $doing_cron_transient = get_transient( 'doing_cron' ); /* * The cron lock (a unix timestamp set when the cron was spawned), * must match $doing_wp_cron (the "key"). */ if ( $doing_cron_transient !== $doing_wp_cron ) { return; }
Needed to change the fix slightly. This should work.
Also maybe consider moving the check/return currently at the end of the loop, to the start of the loop.
// The cron lock: a unix timestamp from when the cron was spawned.
$doing_cron_transient = get_transient( 'doing_cron' );
// Use global $doing_wp_cron lock, otherwise use the GET lock. If no lock, try to grab a new lock.
if ( empty( $doing_wp_cron ) ) {
if ( empty( $_GET['doing_wp_cron'] ) ) {
// Called from external script/job. Try setting a lock.
if ( $doing_cron_transient && ( $doing_cron_transient + WP_CRON_LOCK_TIMEOUT > $gmt_time ) ) {
return;
}
$doing_wp_cron = sprintf( '%.22F', microtime( true ) );
$doing_cron_transient = $doing_wp_cron;
set_transient( 'doing_cron', $doing_wp_cron );
} else {
$doing_wp_cron = $_GET['doing_wp_cron'];
}
}
// Wait x seconds before checking the database.
sleep(2); // Could be WP_CONFIG configurable. Default could be 0, anyone complaining about crons running could set this to 1 or more.
/*
* The cron lock (a unix timestamp set when the cron was spawned),
* must match $doing_wp_cron (the "key").
*/
if ( _get_cron_lock() !== $doing_wp_cron ) {
return;
}
#22
@
16 months ago
My fix did not work as intended. Multiple crons still fired on (nearly) the same moment still get both executed. After the crons run concurrently, the bottom of the loop does (return;) exit the duplicate.
That's where I'm going to leave this, good luck. My "solution" (workaround) is to adjust my code within the crons so that being run twice at the same time is fine. I will also be scheduling crons in via code (not a plug in, sorry WP Control), so that if it's missing, it will re-add it.
Can someone remove me from being assigned the ticket?
#24
in reply to:
↑ 17
@
8 months ago
Can you try to change the cron command? And also make sure it's the only way to call cron. Like DISABLE_WP_CRON -> true and remote calls are disabled (like mentioned above).
* * * * * wget -q -O - "https://DOMAIN.COM/wp-cron.php?doing_wp_cron=`date +%s`" >/dev/null 2>&1
or you can even add nanoseconds
* * * * * wget -q -O - "https://DOMAIN.COM/wp-cron.php?doing_wp_cron=`date +%s.%N`" >/dev/null 2>&1
Related: #57271