Skip to content

SOLR-16586: Log start of SearchHandler#handleRequestBody#1237

Closed
patsonluk wants to merge 3 commits intoapache:mainfrom
cowpaths:patsonluk/SOLR-16586/log-search-handler-start
Closed

SOLR-16586: Log start of SearchHandler#handleRequestBody#1237
patsonluk wants to merge 3 commits intoapache:mainfrom
cowpaths:patsonluk/SOLR-16586/log-search-handler-start

Conversation

@patsonluk
Copy link
Contributor

@patsonluk patsonluk commented Dec 12, 2022

https://issues.apache.org/jira/browse/SOLR-16586

Description

Add logging to start of SearchHandler#handleRequestBody so if processing hangs we know which query is causing that

Solution

Added info logging to the beginning of SearchHandler#handleRequestBody with the query params

Tests

No test added

Checklist

Please review the following and check all that apply:

  • I have reviewed the guidelines for How to Contribute and my code conforms to the standards described there to the best of my ability.
  • I have created a Jira issue and added the issue ID to my pull request title.
  • I have given Solr maintainers access to contribute to my PR branch. (optional but recommended)
  • I have developed this patch against the main branch.
  • I have run ./gradlew check.
  • I have added tests for my changes.
  • I have added documentation for the Reference Guide

Comment on lines +329 to +331
if (log.isInfoEnabled()) {
log.info("Start Search Query: {}", req.getParamString());
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure I'm a fan of this approach. This could have some huge implications on logging requirements and storage. This is logging every single request right?

Previously it looks like this was logged only for timeouts:

} catch (ExitableDirectoryReader.ExitingReaderException ex) {
        log.warn("Query: {}; ", req.getParamString(), ex);

This should at least be disabled by default.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you for the review! I do understand your concern of extra log info, it's important for our use case as queries can sometimes be totally stuck hence timeout wouldn't get printed.

I do agree that it's probably quite specific to our own scenarios (and we might not really seeing issues like that anymore), perhaps changing it to debug will be more suitable?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's important for our use case as queries can sometimes be totally stuck hence timeout wouldn't get printed.

yea I totally understand that. Its always nice to have logging but at the same time this subtle change has the ability to blow up existing installs. debug is a decent idea. I thought I saw a jira/pr go around about adding markers to control logging? maybe that makes sense here to try?

I just think we need to be careful about default logging just surprising folks operating Solr.

Copy link
Contributor Author

@patsonluk patsonluk Dec 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes! this is the marker PR #1229 , could definitely use some review on that one too 🙇🏼

As for this one, perhaps we can keep it simple and change it to debug instead? 😊 (change committed)

@magibney
Copy link
Contributor

Doesn't this allow to achieve essentially the same thing (pre-logging requests), by configuring logging to:

org.apache.solr.core.SolrCore.Request=DEBUG

@patsonluk
Copy link
Contributor Author

patsonluk commented Dec 13, 2022

Doesn't this allow to achieve essentially the same thing (pre-logging requests), by configuring logging to:

org.apache.solr.core.SolrCore.Request=DEBUG

That's a good point @magibney ! I guess for our own usage, we were having issues with Search queries in particular and didn't want to enable debug for SolrCore for that, which could create quite a bit of noise.

However, from general Solr perspective, it does not bring much values to have 2 different debug pieces with very similar info. The scope difference - SolrCore.Request vs SearchHandler probably does not warrant the extra change. I will keep the change to our own local version, and retract this PR for now.

Thank you for all the comments and help!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants