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
<maddineni...@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 <thelabd...@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
>>
