8

I use hook_init() to check the users' last access time. If the last access time is yesterday, I increment a counter and set some variables.

The problem is that hook_init() is sometimes executed more that once (i can see this using dsm()) for the same page load, so my code is executed multiple times resulting in wrong variables.

Why is hook_init() executed more than once?
What would the best approach to my problem be? Should I use another hook?

I did some more digging on this: I search for calls to the hook_init() (searched for string module_invoke_all('init');) but found only the core call). I dont know if this can be called differently.

This is my hook_init()

function episkeptis_achievements_init(){
    dsm('1st execution');
    dsm('REQUEST_TIME: '.format_date(REQUEST_TIME, 'custom', 'd/m/Y H:i:s').' ('.REQUEST_TIME.')');
}

and this is the output:

1st execution
REQUEST_TIME: 09/07/2012 11:20:32 (1341822032)

then, changed the dsm() message to dsm('2nd execution'); and executed again, this is the output:

1st execution
REQUEST_TIME: 09/07/2012 11:20:34 (1341822034)
2nd execution
REQUEST_TIME: 09/07/2012 11:22:28 (1341822148)

You can see that the code is executed twice. However, the first time executes an old copy of the code, and the second time the updated copy. There is also a 2 sec time difference.

This is a d7 version with php 5.3.10

  • Use ddebug_backtrace(), it will give you the function backtrace. If it's really called multiple times, then that function will tell you by whom. – Berdir Jul 9 '12 at 9:53
  • 3
    Keep in mind that just because you see multiple dsm()'s, it doesn't mean that the hook is called multiple times. It's also possible that you are in fact executing multiple requests (e.g. because an image is missing that results in a 404 page which is handled by Drupal) – Berdir Jul 9 '12 at 9:55
  • To notice that between 11:22:28 and 11:20:34 the difference is two minutes, not two seconds. In that case, the hook is not executed twice in the same page request, or the value for REQUEST_TIME would be the same. – kiamlaluno Jul 9 '12 at 11:56
  • @kiamlaluno At the second execution which is 2min after the first, I see two REQUEST_TIME, the current time and an older time which happens to be 2sec after the 1st request. This tells me that the code is executed twice. Can not follow your logic. Why do I see a past REQUEST_TIME for the current request? – Mike Jul 9 '12 at 12:36
  • I cannot answer that. I can only say that, if REQUEST_TIME comes from the same page request, its value is the same; there isn't even a two seconds difference. Check there isn't code that alters the value of REQUEST_TIME. – kiamlaluno Jul 9 '12 at 12:44
20

hook_init() is invoked by Drupal only once for each requested page; it is the last step done in _drupal_bootstrap_full().

  // Drupal 6
  //
  // Let all modules take action before menu system handles the request
  // We do not want this while running update.php.
  if (!defined('MAINTENANCE_MODE') || MAINTENANCE_MODE != 'update') {
    module_invoke_all('init');
  }
  // Drupal 7
  //
  // Let all modules take action before the menu system handles the request.
  // We do not want this while running update.php.
  if (!defined('MAINTENANCE_MODE') || MAINTENANCE_MODE != 'update') {
    // Prior to invoking hook_init(), initialize the theme (potentially a custom
    // one for this page), so that:
    // - Modules with hook_init() implementations that call theme() or
//   theme_get_registry() don't initialize the incorrect theme.
    // - The theme can have hook_*_alter() implementations affect page building
//   (e.g., hook_form_alter(), hook_node_view_alter(), hook_page_alter()),
//   ahead of when rendering starts.
    menu_set_custom_theme();
    drupal_theme_initialize();
    module_invoke_all('init');
  }

If hook_init() is being executed more than once, you should discover why that happens. As far as I can see, none of the hook_init() implementations in Drupal checks it is being executed twice (see for example system_init(), or update_init()). If that is something that can normally happen with Drupal, then update_init() would first check if it has been already executed.

If the counter is the number of consecutive days a user logged in, I would rather implements hook_init() with code similar to the following one.

// Drupal 7
function mymodule_init() {
  global $user;

  $result = mymodule_increase_counter($user->uid); 
  if ($result[0]) {
    // Increase the counter; set the other variables.
  }
  elseif ($result[1] > 86400) {
    // The user didn't log in yesterday.
  }
}

function mymodule_date($timestamp) {
  $date_time = date_create('@' . $timestamp);
  return date_format($date_time, 'Ymd');
}

function mymodule_increase_counter($uid) {
  $last_timestamp = variable_get("mymodule_last_timestamp_$uid", 0);
  if ($last_timestamp == REQUEST_TIME) {
    return array(FALSE, 0);
  }

  $result = array(
    mymodule_date($last_timestamp + 86400) == mymodule_date(REQUEST_TIME),
    REQUEST_TIME - $last_timestamp,
  );
  variable_set("mymodule_last_timestamp_$uid", REQUEST_TIME);

  return $result;
}
// Drupal 6
function mymodule_init() {
  global $user;

  $result = mymodule_increase_counter($user->uid); 
  if ($result[0]) {
    // Increase the counter; set the other variables.
  }
  elseif ($result[1] > 86400) {
    // The user didn't log in yesterday.
  }
}

function mymodule_increase_counter($uid) {
  $last_timestamp = variable_get("mymodule_last_timestamp_$uid", 0);
  $result = array(FALSE, time() - $last_timestamp);

  if (time() - $last_timestamp < 20) {
    return $result;
  }

  $result[0] = (mymodule_date($last_timestamp + 86400) == mymodule_date(REQUEST_TIME));
  variable_set("mymodule_last_timestamp_$uid", time());

  return $result;
}

If hook_init() is invoked two times in row during the same page request, REQUEST_TIME contains the same value, and the function would return FALSE.

The code in mymodule_increase_counter() is not optimized; it is just to show an example. In a real module, I would rather use a database table where the counter, and the other variables are saved. The reason is that Drupal variables are all loaded in the global variable $conf when Drupal bootstraps (see _drupal_bootstrap_variables(), and variable_initialize()); if you use Drupal variables for that, Drupal would load in memory information about all the users for which you saved information, when for each requested page there is only one user account saved in the global variable $user.

If you are counting the number of page visited from the users in consecutive days, then I would implement the following code.

// Drupal 7
function mymodule_init() {
  global $user;

  $result = mymodule_increase_counter($user->uid); 
  if ($result[0]) {
    // Increase the counter; set the other variables.
  }
  elseif ($result[1] > 86400) {
    // The user didn't log in yesterday.
  }
}

function mymodule_date($timestamp) {
  $date_time = date_create('@' . $timestamp);
  return date_format($date_time, 'Ymd');
}

function mymodule_increase_counter($uid) {
  $last_timestamp = variable_get("mymodule_last_timestamp_$uid", 0);
  if ($last_timestamp == REQUEST_TIME) {
    return array(FALSE, 0);
  }

  $result = array(
    mymodule_date($last_timestamp + 86400) == mymodule_date(REQUEST_TIME),
    REQUEST_TIME - $last_timestamp,
  );
  variable_set("mymodule_last_timestamp_$uid", REQUEST_TIME);

  return $result;
}
// Drupal 6
function mymodule_init() {
  global $user;

  $result = mymodule_increase_counter($user->uid); 
  if ($result[0]) {
    // Increase the counter; set the other variables.
  }
  elseif ($result[1] > 86400) {
    // The user didn't log in yesterday.
  }
}

function mymodule_increase_counter($uid) {
  $last_timestamp = variable_get("mymodule_last_timestamp_$uid", 0);
  $result = array(FALSE, time() - $last_timestamp);

  if (time() - $last_timestamp < 20) {
    return $result;
  }

  $result[0] = (mymodule_date($last_timestamp + 86400) == mymodule_date(REQUEST_TIME));
  variable_set("mymodule_last_timestamp_$uid", time());

  return $result;
}

You will notice that in my code I don't use $user->access. The reason is that $user->access could be updated during Drupal bootstrap, before hook_init() is invoked. The session write handler used from Drupal contains the following code. (See _drupal_session_write().)

// Likewise, do not update access time more than once per 180 seconds.
if ($user->uid && REQUEST_TIME - $user->access > variable_get('session_write_interval', 180)) {
  db_update('users')
    ->fields(array(
    'access' => REQUEST_TIME,
  ))
    ->condition('uid', $user->uid)
    ->execute();
}

As for another hook you can use, with Drupal 7 you can use hook_page_alter(); you just don't alter the content of $page, but increase your counter, and change your variables.
On Drupal 6, you could use hook_footer(), the hook called from template_preprocess_page(). You don't return anything, but increase your counter, and change your variables.

On Drupal 6, and Drupal 7, you could use hook_exit(). Bear in mind that the hook is also invoked when the bootstrap is not complete; the code could not have access to functions defined from modules, or other Drupal functions, and you should first check those functions are available. Some functions are always available from hook_exit(), such as the ones defined in bootstrap.inc, and cache.inc. The difference is that hook_exit() is invoked also for cached pages, while hook_init() is not invoked for cached pages.

Finally, as example of code used from a Drupal module, see statistics_exit(). The Statistics module logs access statistics for a site, and as you see, it uses hook_exit(), not hook_init(). To be able to call the necessary functions, it calls drupal_bootstrap() passing the correct parameter, such as in the following code.

  // When serving cached pages with the 'page_cache_without_database'
  // configuration, system variables need to be loaded. This is a major
  // performance decrease for non-database page caches, but with Statistics
  // module, it is likely to also have 'statistics_enable_access_log' enabled,
  // in which case we need to bootstrap to the session phase anyway.
  drupal_bootstrap(DRUPAL_BOOTSTRAP_VARIABLES);
  if (variable_get('statistics_enable_access_log', 0)) {
    drupal_bootstrap(DRUPAL_BOOTSTRAP_SESSION);

    // For anonymous users unicode.inc will not have been loaded.
    include_once DRUPAL_ROOT . '/includes/unicode.inc';
    // Log this page access.
    db_insert('accesslog')
      ->fields(array(
      'title' => truncate_utf8(strip_tags(drupal_get_title()), 255), 
      'path' => truncate_utf8($_GET['q'], 255), 
      'url' => isset($_SERVER['HTTP_REFERER']) ? $_SERVER['HTTP_REFERER'] : '', 
      'hostname' => ip_address(), 
      'uid' => $user->uid, 
      'sid' => session_id(), 
      'timer' => (int) timer_read('page'), 
      'timestamp' => REQUEST_TIME,
    ))
      ->execute();
  }

Update

Maybe there is some confusion about when hook_init() is invoked.

hook_init() is invoked for each page request, if the page is not cached. It is not invoked once for each page request coming from the same user. If you visit, for example, http://example.com/admin/appearance/update, and then http://example.com/admin/reports/status, hook_init() will be invoked twice: one for each page.
"The hook is invoked twice" means there is a module that executes the following code, once Drupal has completed its bootstrap.

module_invoke_all('init');

If that is the case, then the following implementation of hook_init() would show the same value, twice.

function mymodule_init() {
  watchdog('mymodule', 'Request time: !timestamp', array('!timestamp' => REQUEST_TIME), WATCHDOG_DEBUG);
}

If your code shown for REQUEST_TIME two values for which the difference is 2 minutes, as in your case, then the hook is not invoked twice, but it is invoked once for each requested page, as it should happen.

REQUEST_TIME is defined in bootstrap.inc with the following line.

define('REQUEST_TIME', (int) $_SERVER['REQUEST_TIME']);

Until the currently requested page is not returned to the browser, the value of REQUEST_TIME doesn't change. If you see a different value, then you are watching the value assigned in a different request page.

  • I did some testing based on your suggestions. REQUEST_TIME does not contain the same value as you can see in the updated question. I tried to find invocations of hook_init() but found none except one in the core. Maybe I am not looking the right way. Finally, the hook_exit() seems to do the trick, so I will accept this answer. I am however looking for answers as to why hook_init() is called twice. As a side question, you suggest to use a database table instead of variable_set/get. Why is this not recommended, variable_set/get use a db table. – Mike Jul 9 '12 at 9:08
  • Drupal variables use a database table, but they are loaded all in memory when Drupal bootstraps. For each served pages, Drupal bootstraps all times, and there is just a user account associated with a page request. If you use Drupal variables, you would load in memory information about user accounts that are not necessary, as just one of the user accounts is used. – kiamlaluno Aug 25 '12 at 12:26
8

I remember this happening a lot in Drupal 6 (not sure if it still does in Drupal 7), but I never found out why. I seem to remember seeing somewhere that Drupal core does not call this hook twice though.

I always found the easiest way around it was use a static variable to see if the code has already been run:

function MYMODULE_init() {
  static $code_run = FALSE;

  if (!$code_run) {
    run_some_code();
    $code_run = TRUE;
  }
}

That'll ensure it only gets run once in a single page load.

  • Definitively, that is not what Drupal does. – kiamlaluno Jul 7 '12 at 8:24
  • 2
    It's not what core does, but it definitely happens (I've just confirmed that on three legacy Drupal 6 sites, all running mostly different contrib modules). It's a real head-scratcher but I haven't got time to debug 'em at the moment. I suspect it's one of the more regularly used contrib modules (maybe pathauto or global redirect), but I don't want to point fingers. Not really sure why your answer was downvoted though (or mine for that matter), it looks like good information to me. I've upvoted to restore the balance a bit :) – Clive Jul 7 '12 at 13:28
  • I mean that Drupal doesn't have such checking in its hook_init() implementations, and some of them would gladly avoid to be executed twice in row. It is also probable the OP wants hook_init() be executed once per day, if the counter counts the number of consecutive days the users have logged in on the site. – kiamlaluno Jul 7 '12 at 14:06
  • 1
    Ah ok I get what you mean now, yeah the above static pattern is just the one I've used in the past to get around the issue of it being called twice in the same page load; it's not ideal (ideal would be to find out what's invoking it the second time) but as a quick-fix it'll do the trick. What you say about the consecutive days sounds right, probably better that the OP's hook_init checks to see if it's run once already for the day and bails out if it has. Then the whole thing becomes a non-issue anyway – Clive Jul 7 '12 at 14:54
5

You might find hook_init() is called multiple times if there is any AJAX happening on the page (or you're loading images from a private directory - though I'm not sure about that as much). There are a few modules that use AJAX to help bypass page caching for certain elements for example - easiest way to check is to open up the net monitor in your debugger of choice (firefox or web inspector) and having a look to see if any requests are made that could be triggering the bootstrap process.

You'll only get the dpm() on the next page load though if it is an AJAX call. So say you refresh the page 5 minutes later, you'll get the AJAX call from 5 minutes ago's init message as well as the fresh one.

An alternative to hook_init() is hook_boot() which is called before any caching is done at all. No modules are loaded in yet either, so you really don't have much power here apart from setting global variables and running a few Drupal functions. It's useful for bypassing regular level caching (but won't bypass agressive caching).

1

In my case, this behaviour was caused by the Administration Menu module (admin_menu).

hook_init wasn't getting called each request but admin menu would cause /js/admin_menu/cache/94614e34b017b19a78878d7b96ccab55 to be loaded by the user's browser very shortly after the main request, triggering another drupal bootstrap.

There will be other modules that do similar things but admin_menu is probably one of the more commonly deployed ones.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.