Like most people, I don’t like it when my basic needs aren’t met. Recently, I had the basic need to know when a WordPress [pseudo-]cron job had last run. It turns out, WordPress doesn’t provide a straightforward way of showing this information. In fact, it doesn’t even provide an in-built way to log this information. WTF?

And so it begins…

First, to explain the why. We noticed our website was running into issues around the same time, on the same day of the week, on several occasions. It wasn’t happening weekly, but the recurring day and time of day was too frequent to be a coincidence. Naturally, my attention turned towards WP Cron.

There’s a link above that explains some of the reasons WP Cron sucks, but one of the biggest reasons is that it runs on every request. Ugh. I understand the fundamental reason: the real cron is configured on the server, and given the multitude of environments in which WordPress might run, it can never be assumed that the real cron will be accessible and configurable by it.

Checking for overdue cron tasks on every request is an ugly solution, but at least it kicks off cron jobs in a new process, I guess…

Logging the unloggable (not a word)

After spending some quality time with /wp-includes/cron.php and /wp-cron.php, I had a few ideas about how I might be able to create a makeshift cron job logger:

  • filter cron_request
  • filter unschedule_event
  • filter schedule_event

Filtering cron_request

The first option seemed like a no-brainer. The cron is (programmatically) started by a direct call to spawn_cron, or an indirect call to wp_cron. Within spawn_cron, the cron_request filters are applied. This looks like the right filter to use.

No dice. Filtering cron_request, was a bust. All that gets passed to the callback is the URL that was requested (i.e. the path to wp-cron.php), the current date/time (passed as key with the value of $doing_wp_cron) and an array of arguments that aren’t very useful for logging which cron tasks are actually being run. On to the second option.

Filter unschedule_event

I saw this block of code in wp-cron.php and was filled with hope:

// Check lock if ( $doing_cron_transient != $doing_wp_cron ) return;

foreach ( $crons as $timestamp => $cronhooks ) {
    if ( $timestamp > $gmt_time )
        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.
             *
             * @internal
             * @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 )
                return;
        }
    }
}

Notice the wp_unschedule_event call. I know that for both single and recurring cron tasks, this function is called. I also know there’s a schedule_event filter, so there must be an unschedule_event filter too, right? Don’t be stupid. Of course there isn’t, that would be too (consistent|easy|sensible|un-WP). If you’re looking for consistency, WordPress (and PHP, actually) is not the place to find it.

So, to reiterate, there’s no unschedule_event filter. WTF?! I’m suddenly reminded of this illustration of good code vs. bad code. Let’s move on.

An idea interjects!

After getting pissed off with WP for not using apply_filters('unschedule_event') (and probably getting distracted), I temporarily entertained the idea of just filtering get_option for requests for the cron option (yea, you can do that)). Theoretically, it would only be called while performing actions related to the cron (one can dream), but it introduced the issue of knowing the context from which get_option('cron') had been called (i.e. during a cron run, an installation, loading of an admin page, etc.).

I decided to use debug_backtrace to trace back through the call stack to figure it out. It yielded the results I wanted, more or less, but it felt too dirty and inefficient to filter get_option. Still, it was a useful exercise, as the backtrace code would come in handy later.

Filtering schedule_event

The $timestamp (next scheduled run time), $hook (cron job name) and an array of arguments all get passed to the filter callback — just what I need for logging. This is definitely the most promising of all the approaches so far.

However, there’s still the issue of context. apply_filters('schedule_event') is called in wp_schedule_single_event and wp_schedule_event, but those functions aren’t only called when the WP Cron runs, they may also be called when a new task is being added, via a plugin like Crontrol, or while a plugin is being installed, or for any number of reasons from any plugin or theme.

The solution was to take the code I’d sketched out while testing the filter for get_option('cron') and use it in my schedule_event filter callback to determine the likelihood that the cron is actually running. It looks something like this:

class My_Cron_Log_Class {

    /* ...other functions here... */

    public function my_cron_schedule_filter_function($event) {

        // I want to know what the entry point is, so, before I look through, reverse the $debug_backtrace array
        $backtrace = array_reverse(debug_backtrace(false), true);

        // Certain files/functions should be present in the trace if this cron run is legit: wp-cron.php (file), wp-crontrol.php (file), wp_reschedule_event (func) wp_schedule_single_event (func)... 
        $found_cron_call = false;
        $rescheduled = false;
        $single = false;
        $call_to = false;
        $call_origin = false;

        // Find out what triggered the call...
        foreach ($backtrace as $i => $trace) {

            if (preg_match('/(wp-cron(trol)?.php)$/', $trace['file'], $preg_matches)) {
                $found_cron_call = $i;
                $call_to = $preg_matches[0];
            }

            switch ($trace['function']) {

                case 'wp_reschedule_event':
                    $rescheduled = true;
                    break;

                case 'wp_schedule_single_event':
                    $single = true;
                    break;
            }
        }

        if ($found_cron_call !== false && ($rescheduled || $single)) {

            $call_origin = 'auto_run';

            if ($call_to == 'wp-crontrol.php') {
                $call_origin = get_current_user_id();
            }

            // Table has a timestamp field which defaults to current date/time. Fill in the rest...
            $task = array(
                'call_to' => $call_to,
                'call_origin' => $call_origin,
                'task_name' => $event->hook,
                'next_run' => date('Y-m-d h:i:s', $event->timestamp)
            );
            $this->log_task($task);
        }

        return $event;
    }


    private function log_task($task) {
        global $wpdb;

        $wpdb->insert('my_log_table', $task);
        // Yay! Cron logged!
    }

    /* ... more functions here... */

}

I’m going to turn this into a plugin. It feels like something that should be available. The above won’t work if DISABLE_WP_CRON is set to true, but if this is the case, you don’t need such a plugin. Good on you.