Tracing and Forced Reset for cron problems

I would like to propose a modification to to the Drupal v6+ core modules common.inc and modules.inc that will make it possible to easily trace and "unstick" cron execution by simply setting two new variables in the variable table.

This is a problem that seems to crop up from time to time, often (usually?) due to module misconfiguration or defective data. It is however, somewhat problematic to track down which module is misbehaving.

I have tested the core hack detailed below under Drupal 6.14 and it seems to work well so I am submitting it for review and possible inclusion in Drupal Core.

If this proposed modification is accepted, perhaps someone more familiar than I with Drupal user interface coding can put together an interface to set and unset these two added variables at a suitable spot in the admin interface, and create an update script to add the variables to the database automatically.

Firstly, in function drupal_cron_run() (line 2662 in common.inc for Drupal 6.14)
Following the line

	$semaphore = variable_get('cron_semaphore', FALSE);

add the lines

	global $conf;
	$result = db_query('SELECT * FROM {variable} WHERE {name} LIKE \'cron%\'');
	while ($variable = db_fetch_object($result)) {
	  $conf[$variable->name] = unserialize($variable->value);
	}
	$crontrace = isset($conf['cron_trace']) ? $conf['cron_trace'] : FALSE;
	$cronreset = isset($conf['cron_reset']) ? $conf['cron_reset'] : FALSE;
	if ($crontrace) {
	  watchdog('cron', "Cron invoked", array(), WATCHDOG_NOTICE);
	  if ($cronreset) $semaphore = FALSE;
	  variable_set('cron_reset', FALSE);
	}

Reading in from the data table directly ensures that the intended values for the two new variables 'cron_trace' and 'cron_reset' will be read no matter what else is happening in the system. This will take considerably longer than reading the cached variable value using the variable_get() function but as cron is normally invoked daily or, worst case typically hourly, the additional overhead is negligible.

Now, if the variable 'cron_trace' is true (non-zero), a watchdog notice will be issued indicating the invocation of cron. In addition, if 'cron_reset' is true (non-zero), the cron semaphore will be forced to zero, ensuring that cron will actually run.

Secondly, in function module_invoke_all (at the end of modules.inc - (line 464 in modules.inc for Drupal 6.14), modify the lines

	  foreach (module_implements($hook) as $module) {
	    $function = $module .'_'. $hook;
	    $result = call_user_func_array($function, $args);

to the following...

	  foreach (module_implements($hook) as $module) {
	    $function = $module .'_'. $hook;

	    $crontrace = variable_get('cron_trace', FALSE);
	    if ($crontrace && $hook == 'cron')
	      watchdog('cron', "$function invoked.", array(), WATCHDOG_NOTICE);
	    $t1 = gettimeofday();
	    $result = call_user_func_array($function, $args);
	    $t2 = gettimeofday();
	    if ($crontrace && $hook == 'cron') {
	      $secs = $t2['sec'] - $t1['sec'];
	      $usec = $t2['usec']- $t1['usec'];
	      if ($usec < 0) { $usec += 1000000; $secs -= 1; }
	      $msg = sprintf("%s ran for %d.%06d seconds.", $function, $secs, $usec);
	        watchdog('cron', $msg, array(), WATCHDOG_NOTICE);
	    }

This will then log to the watchdog table each and every cron hook invocation, and upon return from the hook function, the execution time for that hook will also be recorded.

Now add to the variable table in the database the following rows (using phpMyAdmin or other suitable database tool) ...

Now the detailed per-hook trace of a cron invocation can be enabled by setting the cron_trace variable to 'i:1;' (php serialized representation of integer value 1) and after invoking cron the results can be viewed in the watchdog log.

If cron is actually stuck - reporting that it is already running or has run for too long in the watchdog log, you will need to also set the variable 'cron_reset' to 'i:1;'

This will now force cron to run and examination of the watchdog log entries generated by the run will help localise which module's cron hook is misbehaving.

The additional watchdog logging calls will only occur when the trace is turned on, and then only if cron hooks are being invoked, so the additional overhead in module_invoke_all is minimal - one cached variable_get, two if statements and two calls to system function gettimeofday().

If anyone borrows this patch and applies it themselves, please remember that in its current form, this is a core hack. As such, it will be overwritten and need to be reapplied whenever you update Drupal.