Support from Acquia helps fund testing for Drupal Acquia logo

Comments

gpk’s picture

Version: 6.16 » 7.x-dev
Category: bug » feature

I'm not convinced this would be regarded as a bug but rather as a feature, in which case there's no chance of it making 6.x and possibly not 7.x even (easy enough to do via hook_form_alter() anyway to avoid hacking core).

jhodgdon’s picture

Version: 7.x-dev » 8.x-dev

I am not sure what you mean by using hook_form_alter() to accomplish this. In Drupal 7, at least, the watchdog logging is done on every search during search_view() [the page callback for the search page].

Anyway, yes it is a feature request and it needs to be put up for consideration in Drupal 8 at this point.

jhodgdon’s picture

Title: Logging searches to watchdog should be configurable » Add ability to turn off watchdog logging of searches
mkalkbrenner’s picture

I understand that you'll treat this as a feature request and I'll be happy if my patch will goes into drupal some day, no matter if it's drupal 7 or 8.

But we run a website on drupal 6 which mostly consists of apachesolr search results. In this case it's a real performance impact that nearly every page request triggers an INSERT statement on the database. That's why consider it as a bug if you cannot turn this off (by configuration). For those who want to see this issue fixed in drupal 6 it might be interesting to get an already patched drupal 6 version from http://drupal.cocomore.com/de/project/drupal

jhodgdon’s picture

Version: 8.x-dev » 7.x-dev
Category: feature » bug
Status: Needs review » Active

OK, I see your point. I'm willing to consider it to be a bug. At this point, we fix bugs in Drupal 7, and then consider backporting to Drupal 6.

jhodgdon’s picture

Title: Add ability to turn off watchdog logging of searches » Watchdog logging of all searches is performance hit; need ability to turn it off
mkalkbrenner’s picture

Thanks a lot!

gpk’s picture

@2: Aahhhhhh yes fair point, in a custom module we can use hook_form_alter() to create an additional setting, and we can implement hook_watchdog() to perform additional or custom logging, but there is no particularly clean way of preventing http://api.drupal.org/api/function/search_view/6 from doing its watchdog call or of intercepting dblog_watchdog() to filter out "search" log entries.

The only options that come to mind - to avoid hacking core - are:

1. override the search module paths that use the search_view callback and replace with a custom implementation that doesn't invoke watchdog()

2. copy modules/watchdog to sites/all/modules/custom/dblog (i.e. make a drop-in replacement) and there in dblog.module in dblog_watchdog() filter out the messages which have $log-['type'] == 'search'.

Playing devil's advocate: why should search module get special treatment and allow its watchdog calls to be filtered out? Shouldn't we come up with a more generic way of handling this?

And if performance is an issue, maybe that's what syslog.module is for?

jhodgdon’s picture

I see your point, but most modules don't log as much as the search module does, and they mostly log admin tasks like creating nodes, deleting users, etc., rather than ordinary anonymous user tasks like doing a search.

mkalkbrenner’s picture

FileSize
1.82 KB

I adjusted the patch to be applicable against Drupal core 7.0. I also changed the default setting to log the searches for compatibility reasons.

jhodgdon’s picture

Status: Active » Needs work

mkalkbrenner: At this point, we probably can't add anything to the Drupal 7 user interface, so we would either need to (a) push this off to Drupal 8, (b) convince webchick/Dries that this is important for Drupal 7, or (c) add it as a variable_set() without adding in a user interface for setting it (i.e., it would just be something you would set in your settings.php file for a site).

It probably also needs a test to be added to the search test suite.

Also, when you attach patches, please set the issue status to "needs review" so that people know there is a patch, and so that the test bot will run the test suite and make sure the patch doesn't break anything else. Thanks!

Regarding this specific patch:

       // Log the search keys.
-      watchdog('search', 'Searched %type for %keys.', array('%keys' => $keys, '%type' => $info['title']), WATCHDOG_NOTICE, l(t('results'), 'search/' . $info['path'] . '/' . $keys));
+      if (variable_get('search_log_searches_to_watchdog', 1)) {
+        // Log the search keys:
+        watchdog('search', 'Searched %type for %keys.', array('%keys' => $keys, '%type' => $info['title']), WATCHDOG_NOTICE, l(t('results'), 'search/' . $info['path'] . '/' . $keys));
+      }

It's probably not necessary to repeat the "Log the search keys" comment. Also, all comments should end in a . not a :, to comply with Drupal coding standards (see http://drupal.org/node/1354).

mkalkbrenner’s picture

Status: Needs work » Needs review
FileSize
1.79 KB

@jhodgdon:

Also, when you attach patches, please set the issue status to "needs review" so that people know there is a patch, and so that the test bot will run the test suite and make sure the patch doesn't break anything else.

Done.

At this point, we probably can't add anything to the Drupal 7 user interface, so we would either need to (a) push this off to Drupal 8, (b) convince webchick/Dries that this is important for Drupal 7, or (c) add it as a variable_set() without adding in a user interface for setting it (i.e., it would just be something you would set in your settings.php file for a site).

It probably also needs a test to be added to the search test suite.

It was you who turned this feature request into a bug for D7 on March 5, 2010 at 6:53pm ;-)

I adjusted my patch to be compatible to Drupal 7.0. Anything else is up to the maintainers: accept or reject the patch, remove the settings part, port it forward to D8, write tests for it, ...

Or leave it in the issue queue for years like other core issues ;-)
See http://lists.drupal.org/pipermail/development/2008-October/031240.html and http://lists.drupal.org/pipermail/development/2008-November/031310.html

BTW I don't see a blocker to integrate the patch in D7. Until somebody disables the new checkbox, nothing will change. But the user has the option to speed up his system.

jhodgdon’s picture

I realize I turned it into a bug. However, that was nearly a year ago, and since then Drupal 7 has been user-interface-frozen, not to mention released, so things have changed. Meaning that at this point, the people who make the final decisions (webchick/Dries) probably won't accept into Drupal 7 patches that change the user interface.

Regarding "up to the maintainers"... The only way core issues move from being in the issue queue to being committed is if someone who is interested in the issue works on the patch and gets it to a point where it is up to the standards we have for Drupal. It's a community project, and we are all volunteers. We work on what's interesting to us, or what someone finds interesting enough to fund. Despairing about issues staying in the queue forever is not really all that welcome, nor is "that's all I'm doing, you work on it". Besides which, at the moment the core search module doesn't really have an active maintainer, for all practical purposes.

So off-hand I don't know of anyone besides you who is likely to work on fixing up the patch so that it can be committed -- you seem to be the only person who is interested in getting this fixed. I volunteered my time to let you know what you would need to do to get this issue resolved... If you care about this issue, continue to work on it or convince someone else who has time that it's worthwhile. If you don't, it's not likely to go anywhere. That's the reality... sorry!

Berdir’s picture

Stable versions are string-frozen which means that no strings can be added or changed.

What might be possible to get into Drupal 7 at this point is a patch without UI, so that it is only possible to override the setting through $conf in settings.php.

Anyway, If you're worried about watchdog performance, you might want to replace dblog.module with something else, syslog.module for example, or http://drupal.org/project/mongodb.

mkalkbrenner’s picture

@jhodgdon: Please don't get me wrong. It was not my intention to start a flame war here. And I really appreciate your participation.
If a find a bug or a possible improvement in drupal core I'm always posting a patch in the issue queue. And I'll keep doing so. But I don't have the time to keep these patches up-to-date for months and years.
BTW I'm not the only one interested in this issue: #732956: Logging searches to watchdog should be configurable

@Berdir:
Thanks for your hints. I'm aware of syslog and MongoDB. (One year ago dereine and I did a quick and dirty Drupal-5 backport of the mongoDB based watchdog replacement for a customer.)

My intention was to offer a little improvement for normal site administrators. For those who prefer a settings-only version I attached an alternative patch.

jhodgdon’s picture

Yeah. Keeping a patch up to date forever isn't fun. All I'm saying is that the alternative plan would be to take the patch to where it can be committed, and then it's done.

This latest patch looks more promising in that regard, in that it could actually be committed, if it's verified and probably it needs a test. Thanks!

douggreen’s picture

Version: 7.x-dev » 8.x-dev
Status: Needs review » Needs work

I agree with @Bedir, if logging is a performance hit, the solution could be to use a different watchdog implementation (I thought of the exact same solutions, syslog or mongodb_watchdog).

But we might consider a new issue to drupal_alter watchdog in D8. If we had this, we could write a contrib module to filtering any message, not just search messages. I'm not sure however, if adding an alter for watchdog, might introduce additional overhead, instead of solving the problem.

douggreen’s picture

Actually, we can do this already without the new hook, I've done something like this (actually @chx did it) before in a custom module:

<?php
/**
 * implements hook_module_implements_alter().
 */
function nosearch_watchdog_module_implements_alter(&$implementations, $hook) {
  if ($hook == 'watchdog' || $hook == 'cron') {
    // dblog_watchdog() will be called from our own watchdog implementation
    // when necessary.
    // dblog_cron() is not necessary and it won't work. While install tries to
    // kill it with a variable, better safe than sorry.
    unset($implementations['dblog']);
  }
}

/**
 * implements hook_watchdog().
 */
function nosearch_watchdog_watchdog($log_entry) {
  if ($log_entry['type'] != 'search') {
    dblog_watchdog($log_entry);
  }
}

/**
 * implements hook_menu_alter().
 */
function nosearch_watchdog_menu_alter(&$items) {
  $paths = array_keys(dblog_menu());
  foreach ($paths as $path) {
    $items[$path]['access callback'] = FALSE;
  }
}

Can we mark this as 'wontfix'?

mkalkbrenner’s picture

Is someone able to explain why it makes sense to log search requests in the watchdog?
The watchdog is not suitable for statistics.

Logging every search query is like logging every comment that gets posted.

skizzo’s picture

Subscribing (D6)

douggreen’s picture

The solution for D7 is above. This will likely never get changed in D6. The question is does this make sense for D8.

I doubt that the actual logging of the results is the worst bit of search's performance. While this is an easy thing to take out, I'd like to see performance tests to justify it. My gut tells me that this is 1-5% of the total search time, but that's just my gut.

For a performance test, I'd load up a test site with 10,000 nodes (using devel generate), index it (using drush search-reindex), then write two drush commands, one that prepped a file with my search terms (values in and out of the index, single and multiple terms, but probably 90% single terms, don't duplicate searches though) and another that just read the terms from a file and did the search. I'd like to see the xhprof output, but a simple command line time before and after would be a helpful start.

ndewhurst’s picture

Assigned: Unassigned » ndewhurst
Issue summary: View changes
Issue tags: +#SprintWeekend2014

Having a look at this during #SprintWeekend2014 in Boston...

pwolanin’s picture

Logging this to watchdog seems pretty pointless to me - I agree it's not even useful.

Also, if you have page cache, some results (for common keywords) may be in the page cache, so even less point since stats won't be accurate.

ndewhurst’s picture

The first patch here is a conversion of patch #12 to work with current D8 code, including a somewhat verbose description for the config option that alludes to some potential pros and cons of enabling it.
Alternatives include:
(a) Making this logging configurable but defaulting to the "do not log" state.
(b) Making the logging configurable but with a super-succinct description to avoid ambiguity.
(c) Removing the logging altogether.

The second patch here simply removes the logging altogether. In our highly unscientific discussions here at our Boston sprint event, opinions range from making it configurable to stripping it out altogether, tilting slightly toward stripping it out. That line of thinking says this volume of logging for anonymous user events is too expensive (i.e. "any DB insert here is one insert too many"), inconsistent with patterns found elsewhere in core modules, and other modules can provide better search statistics. The argument for keeping this as an option assumes a user base such as site builders who want to install Drupal on a smallish site and have instant access to a basic sampling of search terms.

Note: to @douggreen's point, I haven't performed any proper load testing to get a better idea of the actual performance impact here. Some have made the case that this ought to be removed/removable even if the performance impact is minor (e.g. because stats are better handled by separate modules, for more consistency with other modules, or to limit the overall number of log records).

ndewhurst’s picture

Status: Needs work » Needs review

Changing status to needs review, although I'll still take a stab at writing a test for the previous patch...

Nick_vh’s picture

Both of them look really great and if there is a patch that makes this configurable, I'm ok in getting that in Drupal Core. However, I don't see much value in having to log each search query. Certainly not a functionality of Drupal Core.

I'm voting for the search-watchdog-logging-of-all-searches-removed-1054616-25.patch but I'd love to hear some other opinions.

The last submitted patch, watchdog_searches_logging_configurable-D6.patch, failed testing.

jhodgdon’s picture

Thanks for taking an interest and making a patch!

The problem with simply removing the watchdog() call is that Drupal Core has been doing this over many versions, and people could be relying on it. I thought in fact that there used to be a "common search terms" report, but ... ??? maybe not -- I can't find it in 7 or 8.

Anyway, I don't think we can simply remove the functionality, without at least providing a hook or other mechanism that a contrib module could use to provide the functionality -- as it is in the "removal" patch above, there is not any way I can see for a contrib module to know a search had been done and respond by logging, right?

Regarding the "config" patch, I don't think the config needs to be that complicated. How about just a log_searches config, rather than a two-level-deep parameter config

+logging:
+  log_searches_to_watchdog: true

And in the submitForm() method:

       ->save();
 
+    $search_settings
+      ->set('logging.log_searches_to_watchdog', $form_state['values']['log_searches_to_watchdog'])
+      ->save();

Why have two separate config save calls? can't they be combined?

And finally, I think we would need a test?

jhodgdon’s picture

Status: Needs review » Needs work
jhodgdon’s picture

I went back to the patch in #24, rerolled, and updated with the suggestions in #29. Also added a test. Interdiff wasn't really possible, since the patch didn't apply, but it's not too long of a patch so hopefully that is OK.

When testing this locally, I'm getting an exception "Cannot use a scalar value as an array" in Symfony\Component\DependencyInjection\Compiler\ServiceReferenceGraphNode->addOutEdge() [during the compilation of the Container] during the startup of the last test in this test file. ?!? Very odd.

Anyway, here's the patch, and let's see if the Testbot has the same problem.

jhodgdon’s picture

alexpott tried this patch and couldn't reproduce the test exception I have. So ... probably not real?

jhodgdon’s picture

Status: Needs work » Needs review

Oh and it would help if I set the status to "needs review".

jhodgdon’s picture

Status: Needs review » Needs work

The last submitted patch, 31: 733054-optional-search-logging-31.patch, failed testing.

jhodgdon’s picture

Status: Needs work » Needs review
FileSize
6.65 KB

Reroll. The watchdog() line in SearchController changed (so context was wrong in the if(logging) check), and the config moved to a sub-directory (core-wide apparently).

jhodgdon’s picture

Assigned: ndewhurst » jhodgdon

Status: Needs review » Needs work

The last submitted patch, 36: 733054-optional-search-logging-36.patch, failed testing.

jhodgdon’s picture

Issue tags: -#SprintWeekend2014

Legit failures, looks like this needs work.

jhodgdon’s picture

Status: Needs work » Needs review
FileSize
6.65 KB
762 bytes

Ah, missed one URL change in the reroll.

jhodgdon’s picture

jhodgdon’s picture

FileSize
6.48 KB

Reroll for PSR-4

Status: Needs review » Needs work

The last submitted patch, 43: 733054-optional-search-logging-43.patch, failed testing.

jhodgdon’s picture

Reroll for small context change in config file.

It would be great to get this fairly simple change reviewed...

jhodgdon’s picture

Status: Needs work » Needs review
mparker17’s picture

Assigned: jhodgdon » Unassigned

Code looks fine. Manual testing works too. If testbot comes back green, I'd RTBC it.

dawehner’s picture

  1. +++ b/core/modules/search/src/Controller/SearchController.php
    @@ -40,7 +51,8 @@ public function __construct(SearchPageRepositoryInterface $search_page_repositor
    +      $container->get('config.factory')->get('search.settings')
    

    I kinda dislike if constructor code executes anything as this could trigger arbitrary things, ... maybe just store the configFactory directly?

  2. +++ b/core/modules/search/src/Controller/SearchController.php
    @@ -75,7 +87,9 @@ public function view(Request $request, SearchPageInterface $entity) {
    +          watchdog('search', 'Searched %type for %keys.', array('%keys' => $keys, '%type' => $entity->label()), WATCHDOG_NOTICE);
    

    Can we directly convert the watchdog call to the new logging?

jhodgdon’s picture

Sigh. Up about 25 comments, or maybe it was on another issue, I am pretty sure we were told we *should* grab the search settings out in the constructor. I do not know who to believe.

Regarding the new logging, yes we could, but it's not part of this issue is it? This issue is not changing the logging in any way. It is merely wrapping the existing logging in an if() statement based on the settings. Please file a separate issue.

amitgoyal’s picture

Not sure if we should add full stop in assertNoLink() as well to make it consistent with assertLink().

$this->assertLink('Searched Content for ' . $text . '.', 0, 'Search was logged');
$this->assertNoLink('Searched Content for ' . $text . '.', 'Search was not logged');

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

Sigh. Up about 25 comments, or maybe it was on another issue, I am pretty sure we were told we *should* grab the search settings out in the constructor. I do not know who to believe.

Well, this is JUST my personal oppinion here, I won't block the patch based upon that (no needs work).

Not sure if we should add full stop in assertNoLink() as well to make it consistent with assertLink().

$this->assertLink('Searched Content for ' . $text . '.', 0, 'Search was logged');
$this->assertNoLink('Searched Content for ' . $text . '.', 'Search was not logged');

Excellent observation!

jhodgdon’s picture

Good catch amitgoyal, thanks!

alexpott’s picture

Status: Reviewed & tested by the community » Needs work
  1. +++ b/core/modules/search/config/install/search.settings.yml
    @@ -17,3 +17,4 @@ index:
    +logging: true
    

    We've agreed to make Drupal fast by default. This issue points out that caching makes this inaccurate anyway which is now turned on by default. So let's default this to false.

  2. +++ b/core/modules/search/src/Controller/SearchController.php
    @@ -26,13 +27,23 @@ class SearchController extends ControllerBase {
    +    $this->searchConfig = $search_config;
    
    @@ -40,7 +51,8 @@ public function __construct(SearchPageRepositoryInterface $search_page_repositor
    +      $container->get('config.factory')->get('search.settings')
    

    I agree with @dawehner - inject the service not the config - I would not have held up this patch for only this but given we're going to change the default let's fix this here.

jhodgdon’s picture

Status: Needs work » Needs review
FileSize
6.51 KB
2.47 KB

I don't really get the big difference between doing this in the create()

$container->get('config.factory')->get('search.settings')

and

$container->get('config.factory')

Both of them involve "executing code". But OK, whatever, it doesn't bother me to do it the other way either, and I guess if logging is not enabled, it's a femtosecond faster.

And the config with logging being FALSE is opposite of how it's been in all past versions of Drupal, but that's fine with me too.

So, how about this?

Status: Needs review » Needs work

The last submitted patch, 55: 733054-optional-search-logging-55.patch, failed testing.

jhodgdon’s picture

Status: Needs work » Needs review
FileSize
6.51 KB

Whoops, stray comma in the config.factory line here:

 public static function create(ContainerInterface $container) {
    return new static(
      $container->get('search.search_page_repository'),
      $container->get('config.factory')
    );
 

Removed that. No other changes.

dawehner’s picture

What about #49.2 ?

jhodgdon’s picture

Issue tags: +https://www.drupal.org/requirements

As stated in #50, converting the watchdog() call to use a service etc. seems out of scope for this issue. Isn't there an issue out there to do it across core, if it needs to be done? I really do not want to do it in this issue. This issue is just putting an if() around the existing watchdog call.

Also, it looks like it's being handled in #2272481: Remove usages of watchdog() from forms, plugins and controllers

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

You are right, I already RTBCed this issue.

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 57: 733054-optional-search-logging-57.patch, failed testing.

jhodgdon’s picture

Doh. The test failed because of the default behavior changing. Need to update the test too. :(

jhodgdon’s picture

Status: Needs work » Needs review
Issue tags: -https://www.drupal.org/requirements
FileSize
6.51 KB
6.51 KB

OK, one more try. Sorry about the tag in #59 ?!? copy/paste error, was intending for a different issue. oops.

jhodgdon’s picture

FileSize
1.5 KB
jhodgdon’s picture

I am apparently unable to upload files today, paste links into issues, or ... well I'd better not try to do any commits!

Status: Needs review » Needs work

The last submitted patch, 63: 733054-optional-search-logging-63.patch, failed testing.

jhodgdon’s picture

Status: Needs work » Needs review

OK, one of the (duplicate) patches I uploaded failed on an unrelated testbot glitch. The other one passed. I'll take that as a ringing endorsement from the test bot.

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

Back to RTBC

alexpott’s picture

Status: Reviewed & tested by the community » Needs work
Issue tags: +Needs change record

This needs a small change notice to inform site builders about the change and how to turn on search logging.

Also we need to think about migration - the drupal 6 migration should turn this on - we need to file a migrate followup to do this.

jhodgdon’s picture

Status: Needs work » Reviewed & tested by the community
Issue tags: -Needs change record
alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Committed 2b3cf00 and pushed to 8.x. Thanks!

  • alexpott committed 2b3cf00 on 8.x
    Issue #733054 by jhodgdon, mkalkbrenner, amitgoyal, ndewhurst: Fixed...
jhodgdon’s picture

Thanks! I filed a follow-up issue for migrate: #2305869: Search migration - search logging (new setting)

lussoluca’s picture

FileSize
1.91 KB

SearchController should use ConfigFactoryInterface instead of ConfigFactory type hint in __construct otherwise nobody can change the config.factory service.
But SearchController extends ControllerBase so it already has access to the config.factory service via ControllerBase::config($name) method.

lussoluca’s picture

Status: Fixed » Needs work
jhodgdon’s picture

Status: Needs work » Needs review

Ah, good catch! Assuming the test bot agrees, this looks good. So let's make sure it gets tested...

jhodgdon’s picture

Status: Needs review » Reviewed & tested by the community

Pending test bot agreement, this looks RTBC to me.

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Committed f959ce8 and pushed to 8.x. Thanks!

  • alexpott committed f959ce8 on 8.x
    Issue #733054 followup by lussoluca: Fixed Watchdog logging of all...

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.