You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@solr.apache.org by Alex Deparvu <st...@apache.org> on 2023/02/13 21:07:18 UTC
rid parameter missing from query logs in Solr 9.x
Hi. I am chasing a problem related to a missing rid parameter in Solr 9.x
and I think there was a regression introduced where this param is no longer
logged correctly.
Solr 8 logs, rid=-1 logged with final query after distributed results were
collected:
.... INFO (qtp1482246673-23) [c:gettingstarted s:shard1 r:core_node3
x:gettingstarted_shard1_replica_n1] o.a.s.c.S.Request
[gettingstarted_shard1_replica_n1] webapp=/solr path=/select
params={q=*:*&indent=true&q.op=OR&_=1675975274863} rid=-1 hits=0 status=0
QTime=3
Solr 9 logs:
.... INFO (qtp351877391-20) [c:gettingstarted s:shard2 r:core_node7
x:gettingstarted_shard2_replica_n4] o.a.s.c.S.Request webapp=/solr
path=/select params={q=*:*&indent=true&q.op=OR&useParams=&_=1675975376183}
hits=0 status=0 QTime=6
I narrowed down the issue to a problem with the SearchHandler. the part
that determines if the rid param should be added does not match with the
lifecycle of the ResponseBuilder.
basically the decision to add the param is done in tagRequestWithRequestId
[0] based on the rb.isDistrib flag which will only be computed later in
getAndPrepShardHandler [1], so at the moment where this is supposed to be
added, it's always false. this param will never be logged.
Even though it's just logging, I see this as a potential regression. I
think having this info logged is very valuable.
Looking forward to some more thoughts on this.
best,
alex
[0]
https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L631
[1]
https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L280
Re: rid parameter missing from query logs in Solr 9.x
Posted by Alex Deparvu <st...@apache.org>.
Thanks Houston for taking a look.
I created https://issues.apache.org/jira/browse/SOLR-16656 to track this
and I linked it to SOLR-15790
best,
alex
On Tue, Feb 14, 2023 at 8:41 AM Houston Putman <ho...@apache.org> wrote:
> Thanks for the deep dive Alex,
>
> This is the issue that changed the ordering of this logic:
> https://issues.apache.org/jira/browse/SOLR-15790
>
> I don't think this was intentional, just no one noticed that
> rb.isDistrib hadn't been set at that point. We should probably just
> refactor the rb.isDistrib flag to be computed earlier.
>
> Mind making a JIRA issue about this?
>
> - Houston
>
> On Mon, Feb 13, 2023 at 4:07 PM Alex Deparvu <st...@apache.org> wrote:
>
> > Hi. I am chasing a problem related to a missing rid parameter in Solr 9.x
> > and I think there was a regression introduced where this param is no
> longer
> > logged correctly.
> >
> > Solr 8 logs, rid=-1 logged with final query after distributed results
> were
> > collected:
> > .... INFO (qtp1482246673-23) [c:gettingstarted s:shard1 r:core_node3
> > x:gettingstarted_shard1_replica_n1] o.a.s.c.S.Request
> > [gettingstarted_shard1_replica_n1] webapp=/solr path=/select
> > params={q=*:*&indent=true&q.op=OR&_=1675975274863} rid=-1 hits=0 status=0
> > QTime=3
> >
> > Solr 9 logs:
> > .... INFO (qtp351877391-20) [c:gettingstarted s:shard2 r:core_node7
> > x:gettingstarted_shard2_replica_n4] o.a.s.c.S.Request webapp=/solr
> > path=/select
> params={q=*:*&indent=true&q.op=OR&useParams=&_=1675975376183}
> > hits=0 status=0 QTime=6
> >
> > I narrowed down the issue to a problem with the SearchHandler. the part
> > that determines if the rid param should be added does not match with the
> > lifecycle of the ResponseBuilder.
> > basically the decision to add the param is done in
> tagRequestWithRequestId
> > [0] based on the rb.isDistrib flag which will only be computed later in
> > getAndPrepShardHandler [1], so at the moment where this is supposed to be
> > added, it's always false. this param will never be logged.
> >
> > Even though it's just logging, I see this as a potential regression. I
> > think having this info logged is very valuable.
> > Looking forward to some more thoughts on this.
> >
> > best,
> > alex
> >
> > [0]
> >
> >
> https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L631
> >
> > [1]
> >
> >
> https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L280
> >
>
Re: rid parameter missing from query logs in Solr 9.x
Posted by Houston Putman <ho...@apache.org>.
Thanks for the deep dive Alex,
This is the issue that changed the ordering of this logic:
https://issues.apache.org/jira/browse/SOLR-15790
I don't think this was intentional, just no one noticed that
rb.isDistrib hadn't been set at that point. We should probably just
refactor the rb.isDistrib flag to be computed earlier.
Mind making a JIRA issue about this?
- Houston
On Mon, Feb 13, 2023 at 4:07 PM Alex Deparvu <st...@apache.org> wrote:
> Hi. I am chasing a problem related to a missing rid parameter in Solr 9.x
> and I think there was a regression introduced where this param is no longer
> logged correctly.
>
> Solr 8 logs, rid=-1 logged with final query after distributed results were
> collected:
> .... INFO (qtp1482246673-23) [c:gettingstarted s:shard1 r:core_node3
> x:gettingstarted_shard1_replica_n1] o.a.s.c.S.Request
> [gettingstarted_shard1_replica_n1] webapp=/solr path=/select
> params={q=*:*&indent=true&q.op=OR&_=1675975274863} rid=-1 hits=0 status=0
> QTime=3
>
> Solr 9 logs:
> .... INFO (qtp351877391-20) [c:gettingstarted s:shard2 r:core_node7
> x:gettingstarted_shard2_replica_n4] o.a.s.c.S.Request webapp=/solr
> path=/select params={q=*:*&indent=true&q.op=OR&useParams=&_=1675975376183}
> hits=0 status=0 QTime=6
>
> I narrowed down the issue to a problem with the SearchHandler. the part
> that determines if the rid param should be added does not match with the
> lifecycle of the ResponseBuilder.
> basically the decision to add the param is done in tagRequestWithRequestId
> [0] based on the rb.isDistrib flag which will only be computed later in
> getAndPrepShardHandler [1], so at the moment where this is supposed to be
> added, it's always false. this param will never be logged.
>
> Even though it's just logging, I see this as a potential regression. I
> think having this info logged is very valuable.
> Looking forward to some more thoughts on this.
>
> best,
> alex
>
> [0]
>
> https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L631
>
> [1]
>
> https://github.com/apache/solr/blob/47b7f6c75a43256c41abf4db1e5c0efafc15625e/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java#L280
>