Logging is not working

I did comment out hook_boot (i.e. httpbl_boot()) earlier today, but I'd like to give it another day or so to see what happens.

I have seen two httpbl log messages appear. I've also noticed that the blocking activity on two sites has slowed down to a trickle (as opposed to 30 blocks in the prior 24 hours).

If I understand correctly, blocks that occur during hook_boot will not (cannot) be logged because the subsystem will not yet be initialized. On the other hand, my reading of the API docs concerning hook_init indicate that hook_init does not run on cached pages, so I'm wondering what that means on a site that definitely uses cached pages.

Of the two blocks I saw occur today, both happened after requests for pages that no longer exist on the site. There are a number of sites and outdated Google links that link to some images and other content from an outdated, pre-Drupal instance of the site, so they obviously have not been cached and eventually result in a custom 404 page.

One other thing possibly related to this, and a sanity check request: Honeypot.org seems to have been down all day. I've been unable to browse the site at all since this morning. Could somebody give that a whirl? It seems reasonable to assume that that too would have an impact on the queries from httpbl.

Regarding my sanity check request in #2. Nevermind. Honeypot is finally back. I knew that would happen. ;)

I'm going to close this, yet I may re-open as a separate feature request, but first I want to summarize the dilemma to see if I am understanding it correctly.

While hook_boot() may be the ideal time to block undesired traffic, the block occurs before the watchdog table is available for logging the event, However, is it not also true that httpbl's own table (or a cache thereof) is available?

The information that httpbl tries to add to the log -- when available after hook_init() -- is valuable data for following up on who is getting blocked and why. So what I'm getting at is, why not continue to capture that but instead add it into the httpbl table and then also expose that table to Views, to allow for custom queries and reporting?

Sorry. I didn't realize that closing this would make it drop out of sight. I'm still interested in some feedback regarding the idea of storing the results of the honeypot queries in the httpbl table itself, so that some log info can still be captured at hook_boot() time.

I've already got a little hack going so that I can see the httpbl table in views.

Complicated, yes, but I'm not so sure about "unnecessarily." I think the logging is good for peace of mind, especially after the module has first been added to an environment. In my case, on two sites, it was sort of astonishing to see how much traffic was being blocked, so I really wanted to manually double-check a random set of the blocked IPs at Honeypot, and make sure we were not blocking any desired traffic. Since most of the blocking was occurring in the hook_boot() phase, the only source for data to check on was direct access to the httpbl table.

As I've already mentioned above (#6), I created an includes to expose the httpbl table to Views. This makes it incredibly easy to use Views to pull together a quick page of the blocked traffic, and link the host addresses directly to their Honeyport dossiers. I'd like to clean it up and document it better, and maybe also figure out how to create a default Views for it, then I'll figure out the best way to contribute it. It's my first Views hack.

I am beginning to see your "unnecessarily complicated" point, though. Before the cron task was working I didn't realize these items in the httpbl table weren't supposed to be hanging around as long as they were. The View is nice for testing purposes and the satisfaction of seeing that you're stopping bad guys, but I'm no longer inclined to believe that any more information fields need to be added to the httpbl table.

While typing that last comment I got another positive hit for a greylisted IP, and it logged.

I had just earlier added an experiment to the hook_boot() function which may or may not be responsible. It's a call for the full Drupal bootstrap, right after the test to see if checks are enabled...

/**
 * Implementation of hook_boot().
 */
function httpbl_boot() {
  // Only continue when checks are enabled
  if (variable_get('httpbl_check', HTTPBL_CHECK_NONE) == HTTPBL_CHECK_NONE) {
    return;
  }
// This is an experiment to see if bootstraping here will make it possible to get watchdog messages in hook_boot. 
  include_once "includes/bootstrap.inc";
  drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);  
// End of bootstrap experiment

  if (httpbl_check() == HTTPBL_LIST_BLACK) {
    $message = 'Sorry, %ip has been blacklisted by <a href=\"%ipurl\">http:BL</a>.%honeypot';

    if ($link = variable_get('httpbl_link', NULL)) {
      $word = variable_get('httpbl_word', 'randomness');
      $link = httpbl_honeylink($link, $word);
    }

    $message = strtr($message, array('%ip' => $ip, '%ipurl' => _httpbl_ipdata($ip, ip_address()), '%honeypot' => $link));

    header('HTTP/1.1 403 Forbidden');
    echo $message;
    exit();
  }
}

... and before the first check.

I don't know if this is okay to do, and maybe this is just coincidence, but the very next positive greylist result logged, and that's the first one I've seen get logged in over two days.

Logging will work if the full drupal bootstrap is called in the implementation of hook_boot(), before checking Honeypot. I've modified this from the earlier example above, to only do this if we have a setting for verbose logging.

/**
 * Implementation of hook_boot().
 */
function httpbl_boot() {
  // Only continue when checks are enabled
  if (variable_get('httpbl_check', HTTPBL_CHECK_NONE) == HTTPBL_CHECK_NONE) {
    return;
  }

// Bootstraping here necessary for verbose logging option (to wake up the Watchdog).
  if (variable_get('httpbl_log', FALSE)) {
  	include_once "includes/bootstrap.inc";
  	drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
  }
 
  if (httpbl_check() == HTTPBL_LIST_BLACK) {
    $message = 'Sorry, %ip has been blacklisted by <a href=\"%ipurl\">http:BL</a>.%honeypot';

    if ($link = variable_get('httpbl_link', NULL)) {
      $word = variable_get('httpbl_word', 'randomness');
      $link = httpbl_honeylink($link, $word);
    }

    $message = strtr($message, array('%ip' => $ip, '%ipurl' => _httpbl_ipdata($ip, ip_address()), '%honeypot' => $link));

    header('HTTP/1.1 403 Forbidden');
    echo $message;
    exit();
  }
}

For testing purposes on sites with low malicious traffic, you can simply insert a watchdog call right after the bootstrap, and if you're set for verbose logging you'll have plenty of annoying messages in the logs.

I'm not clear on your suggestion. There is no watchdog module in Drupal 6.

I'm certainly no expert on Drupal's bootstrap process, but my reading of the API documentation (http://api.drupal.org/api/drupal/includes--bootstrap.inc) on that process is that, because of the httpbl implementation of hook_boot(), at that point we are already in the boot process of the request life-cycle, but the question is at which phase? The variables system doesn't even become available until phase 6 (and there are only 9 phases).

So, I could be wrong, but I don't think this has the effect of re-initiating a full bootstrap, but is more like waiting until the full bootstrap process is complete. I'm certainly open to an alternative approach, if anyone has something specific to suggest.

By the way, I have this running in two production environments, and in the last 24 hours it has blocked over 18 visitors, including 3 blacklisted, and they've all been logged, and I'm not seeing any ill effects on the rest of the site.

@praseodym #15

Actually I'm not completely sure if we should keep hook_boot at all...If I remove hook_boot, then verbose logging will work as expected, solving this issue.

IMHO, the overall (and fantastic!) value of this module is its ability to identify malicious traffic as early as possible and add any blacklisted visitors to the {access} table, so that I don't have to find them and add them myself. And when that happens I'd like to see it in the logs. If you "fix" logging by removing hook_boot(), it is only "fixed" insofar as a lot of the blocking is no longer occurring either.

I'm running sites in normal page caching mode, and since hook_init() is not invoked on cached pages that would mean many lost opportunities to ban malicious traffic as soon as possible, before it has already initiated a full session, loaded all modules and crawled around in the site until it reaches an un-cached page. It's true enough that logging occurs at that point, but what isn't occurring, for most pages, is any grey and/or blacklisting at all.

In other words, I think the module is mainly doing its desired job in hook_boot(), so if logging is desired it needs to work then. The only other way to initiate blocking that early is to go the alternate route and do it with the Apache module for http:BL, but then we miss the interaction with Drupal.

@ruharen #16

After further reading of drupal bootstrap proccess, my conclussion is that it is not re-initiating a full bootstrap (see drupal_bootstrap()) as you stated, but what it is in fact doing is running later phases of the bootstrap before ending one of them...

My reading of the bootstrap process is that it will not run any later phases unless the earlier phases have been completed. The documentation indicates that the hook_boot() implementation in modules is not invoked until phase 6. So we know we are at least that far along in the process. I went back into my code and tried each of the phases between 6 and Full, with a watchdog debug call immediately thereafter, but no logging occurs until after the full bootstrap has completed.

It's true that this is rarely invoked by other modules, but http:BL is unique in that it is trying to identify between good and malicious traffic so early in a session.

Insofar as negative repercussions are concerned, obviously we don't want those, and I have been testing and monitoring my logs (Drupal and Apache) and have not identified any unusual or problematic consequences. It's quite possible I'm taking a slight performance hit, but it's not noticeable with the current volume of traffic (about 35-50 unique visitors a day, averaging 4-5 pages per visit in an average 2 minutes per visit). It's possible that I'd have to revisit the overall performance issue if/when there was a substantial increase in traffic.

In short, it doesn't appear to be breaking anything or causing problems.

That said, why not at least beta-test blocking in hook_boot(), with logging, allow usage of the module to grow, and see whether or not users begin reporting any noticeable performance problems on high traffic sites? Just a thought.

FYI --

I just took a look at the Visitors module (http://drupal.org/project/visitors). It has a usage count in the 400 range, and it collects and logs visit and page statistics, similar to Google analytics.

I downloaded this module just so I could see the code, and I notice they call a full bootstrap in hook_exit() (line 245). Perhaps that is a viable alternative, though I am not suggesting that at this time, but only noting it as an example of calling a full bootstrap to ensure that logging is available. I have no idea whether or not there are performance issues of any consequence.

I'm giving it a shot in my code -- I've changed hook_boot() to hook_exit() -- to see if it works. So far I can see that logging is happening, but I'll have to wait a little longer to see about the blocking itself.

With all due respect to your performance consequence concerns, I think you may be assuming a worst case scenario. I'm simply suggesting giving it a trial, and if it proves to be a problem, then revisit it later. I really like this module, and though the sites I am using it on are not extremely high in volume, I can already see clearly that malicious traffic is a significant percentage of that volume, so I want to ban it ASAP.

Quick update to #20. I caught a malicious visitor while typing #20, and I know it was not a cached page because it doesn't even exist, so I believe it was caught using hook_exit(). I'll keep an eye out for more.

Why I am so keen on blocking malicious visitors: because I don't want it on my site. In particular, on johnnyguitars.com, our eventual goal is to go full eCommerce. We've got most of the back end for that in place, but want to tighten security as much as we can before turning it all on. For a relatively small site (and a small town guitar store), we do get a lot of legitimate business inquiries (now via telephone) from around the world. However, we also get a lot of bogus web traffic, too, and we'd like to keep it out as much as is possible, especially before we get involved with online financial transactions, etc.

Project Honeypot's http:BL service is a great step towards what we would like to implement. The next step was to see if there was a Drupal implementation for it, and, yes, there is -- thanks to you (praseodym)!

@praseodym #22 said,

If malicious visitors are only requesting cached pages it doesn't really cost you server resources anyway.

Exactly. So what is the objection? I'm not the one expressing resource concerns, especially if it helps me keep unwanted traffic off the site. But hook_init() is not called on cached pages, so if hook_boot() is also not there, then where/when does the blocking and/or logging happen?

Back to the issue of logging...if the objection is to the performance concerns of any implementation of hook_boot(), with the only proposed solution being to not implement hook_boot() at all, then I'm afraid that this shortcuts any real promise of blocking the traffic we want to block, per Honeypot specs.

If hook_boot() is removed, only hook_init() remains, but is not run on cached pages, so no blocking will happen until a human or spider occasionally lands on an un-cached page. If it's a spider, in my opinion, that's too late.

If your objection is to the performance concerns of making logging possible during the implementation of hook_boot(); specifically since it would seem at this point to require waiting for a full bootstrap of the session, then why not just keep the option for Verbose logging as just that, an option. If the user feels that logging has a negative impact, they can simply turn it off. That's the way I have implemented on my site for now. That is, there is no bootstrap call in hook_boot() unless Verbose logging is also enabled.

Btw, I realize the hook_exit() example is likely worthless, but I offerred it as an example (in another module) of a bootstrap call deemed worthy of being there for the overall performance of that modules particular functionality.

Here's a thought...

If the full bootstrap is necessary for logging (and it appears to be), then why not just do that right before the call to watchdog. That way it will not be called for each page in hook_boot(), but only when actually required for logging a grey or blacklisted visitor.

Something like this (without the php tags):

<?php
      // Blacklist?
      if ($response['threat'] > HTTPBL_THRESHOLD_BLACK && $response['type']) {
        if (variable_get('httpbl_log', FALSE)) {
   			include_once "includes/bootstrap.inc";
  			drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
          watchdog('httpbl', '%ip was blacklisted (%response)', array('%ip' => $ip, '%response' => $response['raw']), WATCHDOG_WARNING, _httpbl_ipdata($ip));
        }
        if ($stats) {
          variable_set('httpbl_stat_black', variable_get('httpbl_stat_black', 0)+1);
        }
        $result = HTTPBL_LIST_BLACK;
      }
?>
 

Patch for logging (with an additional benefit for #575906: Question about httpbl_boot()).

Quick review. The unsuccessful "verbose" logging that, IMHO, is important, is the logging of grey and black-listed IPs, and that happens before we've even messaged the bad news to the visitor (be they human or arachnid). There is also one other important error event to log, whether or not the "verbose" logging option is set, and that is if we get an invalid response back from ProjectHoneypot.

My eyeballs are still bleeding from reading about Drupal's bootstrapping and I'm still hard-pressed to come up with definitive answers, but, essentially, in most cases, for a given session, I believe it's the themer that usually finalizes a fully bootstrapped condition. The trouble with this in http:BL is that we've intercepted the potential session so early in the process, before there is even a fully bootstrapped core available to facilitate the watchdog needed for logging. So, in order to log these events, we need to get to the final bootstrap phase.

This can be done with minimal resource impact if we only finish the bootstrap in the event of a grey or blacklist occurrence, or an invalid response. In the case of a grey-list event, we'll be getting a fully themed page anyway for the whitelisting challenge.

So, this patch will facilitate logging for the events I have described above. It also solves the problem noted in #575906: Question about httpbl_boot().

I went rogue with my own custom version of this module nearly two years ago, so I'm not here to re-debate the case for logging (though I still agree it is essential, just as TwoD makes a good case in #30. People DO CARE about this in environments where someone must account for why a user is being banned). I'm commenting here because I have some new information on this, however it is only useful in regards to Drupal 7.

A quick review: The reason that a bootstrap is required to enable logging of nuisance IPs in httpBL (D6) is that they are trapped and grey/blacklisted before watchdog service is available to tell us why they were rejected.

The good news is that in D7 this bootstrap is no longer required for logging. Here's why:

In Drupal 7, whenever a module is enabled, Drupal calls _system_update_bootstrap_status(), which calls bootstrap_hooks(), which returns an array of critical hooks that force modules to always be loaded. This array in D7 includes boot, exit, watchdog and language_init. The same array in the same function in Drupal 6 only included boot and exit. The same array in the same function in Drupal 5 only included init and exit.

So, the short version: Drupal 7 makes sure that watchdog services are available to any module that uses hook_boot(), as does httpBL.

I've recently ported my custom version to D7 and have been running it on one production site for about two weeks, with no problems. Along the way I discovered by accident that the logging was working, even though I had commented out my custom lines forcing the bootstrapping in the event of grey/blacklisting event. I finally got around to researching the API for how this was possible, and that's when I found what I have reported above. So now I have removed those lines altogether and logging is still working.

Reply for #30...

I understand you needed a solution last September, but I was just reading your comment and thought I'd reply, for what it's worth.

I created a work around a long time ago for the non-logging log function of httpBL. By exposing the cache table to Views, you can see a quick report of blocked IPs, with links to Project Honeypot that will show you why they were considered threatening.

My solution has languished in "needs review" status in this queue for nearly two years, but I've been using it on multiple sites for just as long, with no troubles.

#575168: Views Support for http:BL

Fixed in an alternate dev fork that should be published soon.

Fixed in 6.x-2.x-dev and ported to 7.x.