You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by Timothy Potter <th...@gmail.com> on 2013/04/25 19:12:09 UTC
Need to log query request before it is processed
I would like to log query requests before they are processed.
Currently, it seems they are only logged after being processed. I've
tried enabling a finer logging level but that didn't seem to help.
I've enabled request logging in Jetty but most queries come in as
POSTs from SolrJ
I was thinking of adding a query request logger as a <first-component>
but wanted to see what others have done for this?
Thanks.
Tim
Re: Need to log query request before it is processed
Posted by Sudhakar Maddineni <ma...@gmail.com>.
I see.Thanks for sharing.
-Sudhakar.
On Friday, April 26, 2013, Timothy Potter wrote:
> Solved this using a custom SearchHandler and some Log4J goodness.
> Posting here in case anyone has need for logging query request before
> they are executed, which in my case is useful for tracking any queries
> that cause OOMs
>
> My solution uses Log4J's NDC support to log each query request before
> it is processed ... the trick was that the SolrCore.execute method
> logs at the very end so I wasn't able to push and pop the NDC from
> first- and last- SearchComponents respectively. In other words,
> SolrCore logs the query after all the search components complete so I
> couldn't pop the NDC stack in a last-component.
>
> Consequently, I created a simple extension to SearchHandler that
> relies on the SolrRequestInfo close hook to pop the NDC:
>
> public class NDCLoggingSearchHandler extends SearchHandler implements
> Closeable {
> private static final Logger log =
> Logger.getLogger(NDCLoggingSearchHandler.class);
> private static final AtomicInteger ndc = new AtomicInteger(0);
>
> public void handleRequest(SolrQueryRequest req, SolrQueryResponse rsp)
> {
> SolrRequestInfo.getRequestInfo().addCloseHook(this);
> NDC.push("Q:"+ndc.incrementAndGet());
> log.info(req.getParamString());
> super.handleRequest(req, rsp);
> }
>
> public void close() throws IOException {
> NDC.remove();
> }
> }
>
>
> Now I get nice logging like:
> 2013-04-26 19:07:52,545 [qtp1480462011-13] INFO
> analytics.solr.NDCLoggingSearchHandler Q:20 - indent=true&q=*:*&wt=xml
> 2013-04-26 19:07:52,717 [qtp1480462011-13] INFO solr.core.SolrCore
> Q:20 - [solr_signal] webapp=/solr path=/select
> params={indent=true&q=*:*&wt=xml} hits=25389931 status=0 QTime=172
>
> The "Q:20" part is the NDC.
>
> Cheers,
> Tim
>
> PS - I am so happy that Mark switched things to Log4J for 4.3 -
> https://issues.apache.org/jira/browse/SOLR-3706 +1x10
>
> On Thu, Apr 25, 2013 at 5:44 PM, Sudhakar Maddineni
> <maddinenidev@gmail.com <javascript:;>> wrote:
> > HI Tim,
> > Have you tried by enabling the logging levels on httpclient, which is
> > used by solrj classes internally?
> >
> > Thx,Sudhakar.
> >
> >
> > On Thu, Apr 25, 2013 at 10:12 AM, Timothy Potter <thelabdude@gmail.com<javascript:;>
> >wrote:
> >
> >> I would like to log query requests before they are processed.
> >> Currently, it seems they are only logged after being processed. I've
> >> tried enabling a finer logging level but that didn't seem to help.
> >> I've enabled request logging in Jetty but most queries come in as
> >> POSTs from SolrJ
> >>
> >> I was thinking of adding a query request logger as a <first-component>
> >> but wanted to see what others have done for this?
> >>
> >> Thanks.
> >> Tim
> >>
>
Re: Need to log query request before it is processed
Posted by Timothy Potter <th...@gmail.com>.
Solved this using a custom SearchHandler and some Log4J goodness.
Posting here in case anyone has need for logging query request before
they are executed, which in my case is useful for tracking any queries
that cause OOMs
My solution uses Log4J's NDC support to log each query request before
it is processed ... the trick was that the SolrCore.execute method
logs at the very end so I wasn't able to push and pop the NDC from
first- and last- SearchComponents respectively. In other words,
SolrCore logs the query after all the search components complete so I
couldn't pop the NDC stack in a last-component.
Consequently, I created a simple extension to SearchHandler that
relies on the SolrRequestInfo close hook to pop the NDC:
public class NDCLoggingSearchHandler extends SearchHandler implements
Closeable {
private static final Logger log =
Logger.getLogger(NDCLoggingSearchHandler.class);
private static final AtomicInteger ndc = new AtomicInteger(0);
public void handleRequest(SolrQueryRequest req, SolrQueryResponse rsp) {
SolrRequestInfo.getRequestInfo().addCloseHook(this);
NDC.push("Q:"+ndc.incrementAndGet());
log.info(req.getParamString());
super.handleRequest(req, rsp);
}
public void close() throws IOException {
NDC.remove();
}
}
Now I get nice logging like:
2013-04-26 19:07:52,545 [qtp1480462011-13] INFO
analytics.solr.NDCLoggingSearchHandler Q:20 - indent=true&q=*:*&wt=xml
2013-04-26 19:07:52,717 [qtp1480462011-13] INFO solr.core.SolrCore
Q:20 - [solr_signal] webapp=/solr path=/select
params={indent=true&q=*:*&wt=xml} hits=25389931 status=0 QTime=172
The "Q:20" part is the NDC.
Cheers,
Tim
PS - I am so happy that Mark switched things to Log4J for 4.3 -
https://issues.apache.org/jira/browse/SOLR-3706 +1x10
On Thu, Apr 25, 2013 at 5:44 PM, Sudhakar Maddineni
<ma...@gmail.com> wrote:
> HI Tim,
> Have you tried by enabling the logging levels on httpclient, which is
> used by solrj classes internally?
>
> Thx,Sudhakar.
>
>
> On Thu, Apr 25, 2013 at 10:12 AM, Timothy Potter <th...@gmail.com>wrote:
>
>> I would like to log query requests before they are processed.
>> Currently, it seems they are only logged after being processed. I've
>> tried enabling a finer logging level but that didn't seem to help.
>> I've enabled request logging in Jetty but most queries come in as
>> POSTs from SolrJ
>>
>> I was thinking of adding a query request logger as a <first-component>
>> but wanted to see what others have done for this?
>>
>> Thanks.
>> Tim
>>
Re: Need to log query request before it is processed
Posted by Sudhakar Maddineni <ma...@gmail.com>.
HI Tim,
Have you tried by enabling the logging levels on httpclient, which is
used by solrj classes internally?
Thx,Sudhakar.
On Thu, Apr 25, 2013 at 10:12 AM, Timothy Potter <th...@gmail.com>wrote:
> I would like to log query requests before they are processed.
> Currently, it seems they are only logged after being processed. I've
> tried enabling a finer logging level but that didn't seem to help.
> I've enabled request logging in Jetty but most queries come in as
> POSTs from SolrJ
>
> I was thinking of adding a query request logger as a <first-component>
> but wanted to see what others have done for this?
>
> Thanks.
> Tim
>