[wp-trac] [WordPress Trac] #57924: Cron Goes Missing. _set_cron_array called with incorrect number of crons
WordPress Trac
noreply at wordpress.org
Wed Mar 15 17:53:20 UTC 2023
#57924: Cron Goes Missing. _set_cron_array called with incorrect number of crons
--------------------------+------------------------------
Reporter: j3gaming | Owner: j3gaming
Type: defect (bug) | Status: assigned
Priority: normal | Milestone: Awaiting Review
Component: Cron API | Version: 6.1.1
Severity: normal | Resolution:
Keywords: | Focuses:
--------------------------+------------------------------
Comment (by j3gaming):
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.
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 deleting, hiding the fact it was ever deleted.
--
Ticket URL: <https://core.trac.wordpress.org/ticket/57924#comment:7>
WordPress Trac <https://core.trac.wordpress.org/>
WordPress publishing platform
More information about the wp-trac
mailing list