“Missed Schedule” and wp-cron issues with W3TC Object Cache

Hello @macobserver,

I am sorry about the issue you are having and I am happy to assist you with this.
wp_cron.php has multiple exit points (return; or die(); statements). Can you check please which one fires for you?

Thanks, @vmarko — I appreciate the help. How would I know which one is firing?

Hello @macobserver,

Sorry for the late reply.
Add
error_log(‘im return from line XXX’);
before the statement of interest and check error log after some time.
I hope this helps.

after many tests, I also realized that the object cache prevents my cron from working.
I currently disabled the object cache.
Has a solution been found?

Wordpress 5.2.4
W3TC 0.10.1
PHP Version 7.0.33

Hello @pukos

As said in the previous post wp_cron.php has multiple exit points (return; or die(); statements). Can you check please which one fires for you by adding
error_log(‘im return from line XXX’);
before the statement of interest and check the error log after some time?

This is my wp-cron.php but I cannot find anything on my log file
The strange thing is that if restart the cron service, the scheduled action are fired at least one time

<?php
/**
 * A pseudo-CRON daemon for scheduling WordPress tasks
 *
 * WP Cron is triggered when the site receives a visit. In the scenario
 * where a site may not receive enough visits to execute scheduled tasks
 * in a timely manner, this file can be called directly or via a server
 * CRON daemon for X number of times.
 *
 * Defining DISABLE_WP_CRON as true and calling this file directly are
 * mutually exclusive and the latter does not rely on the former to work.
 *
 * The HTTP request to this file will not slow down the visitor who happens to
 * visit when the cron job is needed to run.
 *
 * @package WordPress
 */

ignore_user_abort( true );

/* Don't make the request block till we finish, if possible. */
if ( function_exists( 'fastcgi_finish_request' ) && version_compare( phpversion(), '7.0.16', '>=' ) ) {
	fastcgi_finish_request();
}

if ( ! empty( $_POST ) || defined( 'DOING_AJAX' ) || defined( 'DOING_CRON' ) ) {
	error_log('im return from line 27');
	die();
}

/**
 * Tell WordPress we are doing the CRON task.
 *
 * @var bool
 */
define( 'DOING_CRON', true );

if ( ! defined( 'ABSPATH' ) ) {
	/** Set up WordPress environment */
	require_once( dirname( __FILE__ ) . '/wp-load.php' );
}

/**
 * Retrieves the cron lock.
 *
 * Returns the uncached <code>doing_cron</code> transient.
 *
 * @ignore
 * @since 3.3.0
 *
 * @global wpdb $wpdb WordPress database abstraction object.
 *
 * @return string|false Value of the <code>doing_cron</code> transient, 0|false otherwise.
 */
function _get_cron_lock() {
	global $wpdb;

	$value = 0;
	if ( wp_using_ext_object_cache() ) {
		/*
		 * Skip local cache and force re-fetch of doing_cron transient
		 * in case another process updated the cache.
		 */
		$value = wp_cache_get( 'doing_cron', 'transient', true );
	} else {
		$row = $wpdb->get_row( $wpdb->prepare( "SELECT option_value FROM $wpdb->options WHERE option_name = %s LIMIT 1", '_transient_doing_cron' ) );
		if ( is_object( $row ) ) {
			$value = $row->option_value;
		}
	}
	error_log('im return from line 71');
	return $value;
}

$crons = wp_get_ready_cron_jobs();
if ( empty( $crons ) ) {
	error_log('im return from line 77');
	die();
}

$gmt_time = microtime( true );

// 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, trying grabbing 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_cron_transient = $doing_wp_cron = sprintf( '%.22F', microtime( true ) );
		set_transient( 'doing_cron', $doing_wp_cron );
	} else {
		$doing_wp_cron = $_GET['doing_wp_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 ) {
	error_log('im return from line 105');
	return;
}

foreach ( $crons as $timestamp => $cronhooks ) {
	if ( $timestamp > $gmt_time ) {
		error_log('im return from line 111');
		break;
	}

	foreach ( $cronhooks as $hook => $keys ) {

		foreach ( $keys as $k => $v ) {

			$schedule = $v['schedule'];

			if ( $schedule != false ) {
				$new_args = array( $timestamp, $schedule, $hook, $v['args'] );
				call_user_func_array( 'wp_reschedule_event', $new_args );
			}

			wp_unschedule_event( $timestamp, $hook, $v['args'] );

			/**
			 * Fires scheduled events.
			 *
			 * @ignore
			 * @since 2.1.0
			 *
			 * @param string $hook Name of the hook that was scheduled to be fired.
			 * @param array  $args The arguments to be passed to the hook.
			 */
			do_action_ref_array( $hook, $v['args'] );

			// If the hook ran too long and another cron process stole the lock, quit.
			if ( _get_cron_lock() != $doing_wp_cron ) {
				error_log('im return from line 141');
				return;
			}
		}
	}
}

if ( _get_cron_lock() == $doing_wp_cron ) {
	delete_transient( 'doing_cron' );
}
error_log('im return from line 151');
die();

I mean, none of the error_log( … XXX) is found on php-fpm.log

@vmarko Would be great to have a replay to understand why any of my error_log(‘im return from line XXX’); is not fired in php-fpm.log

Thank you

Hello @pukos
Sorry for the late reply.

Make a simple script like

<?php
echo 'before logging';
error_log('testXYZ');
echo 'after logging';

and try to find where you are logging errors to.
regular places are:
1. your global web server error log, in /var/log/apache2, /var/log/httpd, /var/log/nginx
2. your vhost web server error log, in the same folders as above or /home/yourname/…/logs
3. wp-content/debug.log if WP_DEBUG is set

I hope this helps!

Thank you @vmarko
I didn’t understood very well where/how to put your “simple script”, anyway I added a lot of “error_log(‘im return from line XXX’);” and I could finally log them.
I attached both the code and the log. I hope you have enough clues to understand why the object cache causes this problem.

THIS IS WP-CRON.PHP

<?php
/**
 * A pseudo-CRON daemon for scheduling WordPress tasks
 *
 * WP Cron is triggered when the site receives a visit. In the scenario
 * where a site may not receive enough visits to execute scheduled tasks
 * in a timely manner, this file can be called directly or via a server
 * CRON daemon for X number of times.
 *
 * Defining DISABLE_WP_CRON as true and calling this file directly are
 * mutually exclusive and the latter does not rely on the former to work.
 *
 * The HTTP request to this file will not slow down the visitor who happens to
 * visit when the cron job is needed to run.
 *
 * @package WordPress
 */

ignore_user_abort( true );

/* Don't make the request block till we finish, if possible. */
if ( function_exists( 'fastcgi_finish_request' ) && version_compare( phpversion(), '7.0.16', '>=' ) ) {
	error_log('im return from line 23');
	fastcgi_finish_request();
}

if ( ! empty( $_POST ) || defined( 'DOING_AJAX' ) || defined( 'DOING_CRON' ) ) {
	error_log('im return from line 27');
	die();
}

/**
 * Tell WordPress we are doing the CRON task.
 *
 * @var bool
 */
define( 'DOING_CRON', true );

if ( ! defined( 'ABSPATH' ) ) {
	/** Set up WordPress environment */
	require_once( dirname( __FILE__ ) . '/wp-load.php' );
}

/**
 * Retrieves the cron lock.
 *
 * Returns the uncached <code>doing_cron</code> transient.
 *
 * @ignore
 * @since 3.3.0
 *
 * @global wpdb $wpdb WordPress database abstraction object.
 *
 * @return string|false Value of the <code>doing_cron</code> transient, 0|false otherwise.
 */
function _get_cron_lock() {
	global $wpdb;

	$value = 0;
	if ( wp_using_ext_object_cache() ) {
		/*
		 * Skip local cache and force re-fetch of doing_cron transient
		 * in case another process updated the cache.
		 */
		$value = wp_cache_get( 'doing_cron', 'transient', true );
	} else {
		$row = $wpdb->get_row( $wpdb->prepare( "SELECT option_value FROM $wpdb->options WHERE option_name = %s LIMIT 1", '_transient_doing_cron' ) );
		if ( is_object( $row ) ) {
			$value = $row->option_value;
		}
	}
	error_log('im return from line 71');
	return $value;
}
error_log('im return from line 75');
$crons = wp_get_ready_cron_jobs();
if ( empty( $crons ) ) {
	error_log('im return from line 77');
	die();
}
error_log('im return from line 81');
$gmt_time = microtime( true );
error_log('im return from line 83');
// The cron lock: a unix timestamp from when the cron was spawned.
$doing_cron_transient = get_transient( 'doing_cron' );
error_log('im return from line 86');
// Use global $doing_wp_cron lock otherwise use the GET lock. If no lock, trying grabbing 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_cron_transient = $doing_wp_cron = sprintf( '%.22F', microtime( true ) );
		set_transient( 'doing_cron', $doing_wp_cron );
	} else {
		$doing_wp_cron = $_GET['doing_wp_cron'];
	}
}
error_log('im return from line 100');
/*
 * 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 ) {
	error_log('im return from line 106');
	return;
}
error_log('im return from line 109');
foreach ( $crons as $timestamp => $cronhooks ) {
	if ( $timestamp > $gmt_time ) {
		error_log('im return from line 112');
		break;
	}

	foreach ( $cronhooks as $hook => $keys ) {

		foreach ( $keys as $k => $v ) {

			$schedule = $v['schedule'];

			if ( $schedule != false ) {
				$new_args = array( $timestamp, $schedule, $hook, $v['args'] );
				call_user_func_array( 'wp_reschedule_event', $new_args );
			}
error_log('im return from line 126');
			wp_unschedule_event( $timestamp, $hook, $v['args'] );
error_log('im return from line 128');
			/**
			 * Fires scheduled events.
			 *
			 * @ignore
			 * @since 2.1.0
			 *
			 * @param string $hook Name of the hook that was scheduled to be fired.
			 * @param array  $args The arguments to be passed to the hook.
			 */
			do_action_ref_array( $hook, $v['args'] );
error_log('im return from line 139');
			// If the hook ran too long and another cron process stole the lock, quit.
			if ( _get_cron_lock() != $doing_wp_cron ) {
				error_log('im return from line 141');
				return;
			}
		}
	}
}
error_log('im return from line 148');
if ( _get_cron_lock() == $doing_wp_cron ) {
	delete_transient( 'doing_cron' );
}
error_log('im return from line 152');
die();

THIS IS THE ACTIONS LOGGED

[19-Oct-2019 06:30:02 UTC] im return from line 75
[19-Oct-2019 06:30:02 UTC] im return from line 81
[19-Oct-2019 06:30:02 UTC] im return from line 83
[19-Oct-2019 06:30:02 UTC] im return from line 86
[19-Oct-2019 06:30:02 UTC] im return from line 100
[19-Oct-2019 06:30:02 UTC] im return from line 109
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 126
[19-Oct-2019 06:30:02 UTC] im return from line 128
[19-Oct-2019 06:30:02 UTC] im return from line 139
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 148
[19-Oct-2019 06:30:02 UTC] im return from line 71
[19-Oct-2019 06:30:02 UTC] im return from line 152

Please @vmarko do not abandon me.
I know it is not a very common problem, but a solution should be useful to many people.

Thank you

Hello @pukos

I am sorry for the late reply.

The script from your log processed 7 scheduled events (processing happens between 128 and 139 msgs).
I.E. it worked those time and there is no problems with “doing_cron” particularly
Here are some possibilities:
1. It worked at that particular time but doesn’t later. You’ll have shorter logs in that case
2. You miss some specific scheduled events, but in general, wp-cron works. If that’s the case – modify:
error_log('im return from line 128');
with
error_log('im return from line 128 ' . $hook);
to see which events it process. In that case you need to know which one you are missing.
3. The event is called as it should be but the problem is in the handler itself.

I hope this helps!

Perhaps a better way to address this issue:

We (now) know that W3TC’s object cache gets in the way of wp-cron for some amount of users. There’s clearly an incompatibility here.

With that in mind, wouldn’t it be better for you to simply patch W3TC’s Object Cache so as not to mess with the doing_cron transient?

It seems like that would be the best solution here, especially given that it seems like troubleshooting this is made very difficult for whatever reason.

We’ve pinpointed a very specific problem. If you want to give us a debug build or something that logs in a way that’s valuable for you, that’s one thing. But to ask users to edit code and hack together their own debug builds seems really dangerous, and probably not entirely helpful for your troubleshooting, either.

Hello @macobserver

I’ve spoken with the team regarding this issue.
The test showed it’s not the doing_cron.
Of course, everyone is welcome to participate in this free product.
This looks like some host-specific issue since there were no other issues reported of this kind.
What we offered in the previous message is a method to debug the issue further.
We can, of course, investigate this issue for you on your hosting environment but in this case, I can only offer you our Professional support in Performance>Support.
Once again I am sorry about the issue you are having.

We have an annual subscription to this, and aren’t using the free product. Didn’t realize support for the product was bifurcated. I’ll file in the other channel.