Fixing a Drupal Cron error

I took me a couple of hours the find and fix a very annoying Drupal cron error. To be sure that I don't get bitten by it again I'm writing this post. Hopefully somebody will find it useful in the future :). ANyway: the rest of this blog is quite technical. So be warned!

Situation:

We developed a website for a customer using the open source CMS drupal.

Symptoms:

We created a module with a cron hook to update content from an external source into our website. This cron hook didn't run well when used by crontab. When requested from the browser it displayed a "acces denied" page: rendered twice…

Analysis:

If we take a look at cron.php we see that it does two things:

drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
drupal_cron_run();

As the bootstrap runs normally for the rest op the pages, the drupal_cron_run() must be the problem. In any advanced other development platform (i.e. .NET) we would be able to connect a debugger and step into the code to find the problem.

But not with PHP. In this case I had to login via SSH and edit the files via VIM. Inserting debug statements as I went. (Poor men's debugging avant la lettre).

If we have a look at drupal_cron_run() we see that it calls:

module_invoke_all('cron');

I.E. all modules which define a hook_cron() will be called.

via the module_invoke_all. I was able to find the misbehaving module: search. When I removed the call to search_cron from the list, the problem was gone. So let's have a look at: search_cron. The main work of this function is done by:

foreach (module_list() as $module) {
    module_invoke($module, 'update_index');
  }

It tries to invoke the "update_index" hook on all modules. And as the API docs says: "Update Drupal's full-text index for this module."

With some more var_dumps and prints I came to the conclusion that the node module was the problem.

Here is the code for node_update_index:

$result = db_query_range("SELECT n.nid FROM {node} n LEFT JOIN {search_dataset} d ON d.type = 'node' AND d.sid = n.nid WHERE d.sid IS NULL OR d.reindex <> 0 ORDER BY d.reindex ASC, n.nid ASC", 0, $limit);

while ($node = db_fetch_object($result)) {
    _node_index_node($node);
}

More var_dumps and print statements brougt me to the NID's of the faulting nodes. There where two nodes of the type: "multichoice" of the "quiz" module.  

The problem is within the call to the

$node = node_build_content($node, FALSE, FALSE);

In _node_index_node. As we can see it 2nd & 3th parameter are FALSE. node_build_content will call node_invoke and this will call HOOK_view() which in the case of the multichoice has this code:

function multichoice_view($node, $teaser = FALSE, $page = FALSE) {
  if (!$teaser && $page) {
    // This is not necessary:
    //$mynode = node_prepare($node, $teaser);
    $node->content['body'] = array('#value' => multichoice_render_question($node));
    return $node;
  }
  elseif ($teaser) {
    $node = node_prepare($node, $teaser);
    return $node;
  }
  else {
    drupal_access_denied();
    }
}

As we remember: $teaser and $page are set to false. So we fall trough to the last else: "drupal_acces_denied()";

As we have two content nodes of this type the acces denied message is displayed twice.

In the HEAD version of the module it seems to be fixed:

http://drupalcode.org/viewvc/drupal/contributions/modules/quiz/question_types/multichoice/multichoice.module?annotate=1.4#l687

Lessons learned:

• Always keep up to date with modules (the module was updated Jan-5-2010) as it may bite you in strange ways…


• Drupal debugging is hard