Logging in Solrcloud

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Logging in Solrcloud

Matzdorf, Stefan, Springer SBM DE
Hey everybody,

i have a question regarding query-request logging in solr-cloud. I've set the the "org.apache.solr.core.SolrCore.Request"-logger to INFO-level and its logging all those query-requests. So far so good. BUT, as I'm running Solr in cloud mode with 3 nodes and 3 shards per collections (with a replica of 3; distributed about all 3 nodes), i get a logging statement from each node as well as from each shard. That i get it from each node seems quite obvious to me. Different server, different solr-instances...ok. But how could i avoid getting also the logs from the shards itself?

My main problem is, that i would like to measure, classify etc my queries. But for example if i would like to count the number of queries it goes a bit weird. So from one request sent to the cloud i got 5-7 logging statements. (i guess it depends on the results of found documents within a shard?!).


If i could get just one log-statement per node per request (in my case 3) would be good. But even then, i have to do some math to get the exact values. At the first look it seems quite easy, dividing by 3, but thats sadly not the case. So what happens if one node goes down? Then i would just get 2 log-statements. Thats also the reason why i can't set the log-level to INFO just on one node.



Long story short, is there a better way to log queries, then setting "org.apache.solr.core.SolrCore.Request" to INFO???


Thanks in advance?
Reply | Threaded
Open this post in threaded view
|

Re: Logging in Solrcloud

Emir Arnautović
Hi Stefan,
I am not aware of option to log only client side queries, but I think that you can find workaround with what you currently have. If you take a look at log lines for query that comes from the client and one that is result of querying shards, you will see differences - the most simple one, if you are not using solrj for querying, would be wt parameter: e.g. client request might have wt=json while shard requests would have wt=javabin.
There are also parameters that are added by Solr for internal calls so just compare log lines you will find some discriminator in your version of Solr.

HTH,
Emir
--
Monitoring - Log Management - Alerting - Anomaly Detection
Solr & Elasticsearch Consulting Support Training - http://sematext.com/



> On 5 Dec 2017, at 07:58, Matzdorf, Stefan, Springer SBM DE <[hidden email]> wrote:
>
> Hey everybody,
>
> i have a question regarding query-request logging in solr-cloud. I've set the the "org.apache.solr.core.SolrCore.Request"-logger to INFO-level and its logging all those query-requests. So far so good. BUT, as I'm running Solr in cloud mode with 3 nodes and 3 shards per collections (with a replica of 3; distributed about all 3 nodes), i get a logging statement from each node as well as from each shard. That i get it from each node seems quite obvious to me. Different server, different solr-instances...ok. But how could i avoid getting also the logs from the shards itself?
>
> My main problem is, that i would like to measure, classify etc my queries. But for example if i would like to count the number of queries it goes a bit weird. So from one request sent to the cloud i got 5-7 logging statements. (i guess it depends on the results of found documents within a shard?!).
>
>
> If i could get just one log-statement per node per request (in my case 3) would be good. But even then, i have to do some math to get the exact values. At the first look it seems quite easy, dividing by 3, but thats sadly not the case. So what happens if one node goes down? Then i would just get 2 log-statements. Thats also the reason why i can't set the log-level to INFO just on one node.
>
>
>
> Long story short, is there a better way to log queries, then setting "org.apache.solr.core.SolrCore.Request" to INFO???
>
>
> Thanks in advance?

Reply | Threaded
Open this post in threaded view
|

Re: Logging in Solrcloud

Matzdorf, Stefan, Springer SBM DE
To be more precisely and provide some more details, i tried to simplify the problem by using the Solr-examples that were delivered with the solr....
So i started bin/solr -e cloud, using 2 nodes, 2 shards and replication of 2.

To understand the following, it might be important to know, which ports are used:
 node 1: 8983 (leader for shard1 and shard2)
 node 2: 7574 (no leader at all)


In this example i searched for 3 terms in the following order: first on node 1 (8983 - leader) and then on node 2 (7574).

Sample1 (q=test):
    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json

    produced logs:
      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
      2)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1

   

    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json

    produced logs:
      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=17

##############################################################################################################################
##############################################################################################################################

Sample2 (q=foo):
    http://localhost:8983/solr/gettingstarted/select?indent=on&q=foo&wt=json

    produced logs:
      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=foo&NOW=1512474569299&isShard=true&wt=javabin} hits=0 status=0 QTime=0

   

    http://localhost:7574/solr/gettingstarted/select?indent=on&q=foo&wt=json

    produced logs:
      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={q=foo&indent=on&wt=json} hits=0 status=0 QTime=13

##############################################################################################################################
##############################################################################################################################

Sample3 (q=test) NOTE- its the same query as in sample1:
    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json

    produced logs:
      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0

   
    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json

    produced logs:
      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474627254&isShard=true&wt=javabin} hits=0 status=0 QTime=0
      2)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=13

##############################################################################################################################
##############################################################################################################################

Sample4 (q=baa):
    http://localhost:8983/solr/gettingstarted/select?indent=on&q=baa&wt=json

    produced logs:
      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=baa&NOW=1512474709460&isShard=true&wt=javabin} hits=0 status=0 QTime=0
   

    http://localhost:7574/solr/gettingstarted/select?indent=on&q=baa&wt=json

    produced logs:
      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=baa&indent=on&wt=json} hits=0 status=0 QTime=12




Sorry for this messy logs.
I'll try to sumarize....

For queries against the node 1, the leading node, i never got those "short logs". just containing what i was querying. Instead i recieve logs containing all these sharding information. Sometimes 2 equivalent ones (see sample 1) and sometimes just one log (sample 2-4). Mentioned that i got different logs for the same query/request (sample1 vs sample3).

For queries against the node 2, not leading anything, i got those "short logs" everytime. In addition to that, i also recievie sometimes an additional log, containing these sharding information (sample 3).


My assumptions:
afaik, the queried shard is choosen randomly, that would explain why i got different amount of logs for same queries/request. But what i everytime the same, is that the "non-leading node" is the only one that returns the logs i want. I tried some other example (that i do not write down here), and i saw the same result. different amount of logs, that look spreaded randomly, but i never got those "short-logs" from the leading node, just from the "non-leading node".


So the idea of trying to find the difference between logs is not that suitable, because sometimes they aren't present (facing the leading node).

So the question still reminds: how could i log the incoming request in a proper way?


I hope that my problem was clearly described, and someone got an idea whats going on here.
Reply | Threaded
Open this post in threaded view
|

Re: Logging in Solrcloud

Walter Underwood
In 6.5.1, the intra-cluster requests are POST, which makes them easy to distinguish in the request logs. Also, the intra-cluster requests go to a specific core instead of to the collection. So we use the request logs and grep out the GET lines.

We are considering fronting every Solr process with a local nginx server. That will allow us to limit concurrent connections. It will also give us a log of just the client requests.

wunder
Walter Underwood
[hidden email]
http://observer.wunderwood.org/  (my blog)


> On Dec 5, 2017, at 4:25 AM, Matzdorf, Stefan, Springer SBM DE <[hidden email]> wrote:
>
> To be more precisely and provide some more details, i tried to simplify the problem by using the Solr-examples that were delivered with the solr....
> So i started bin/solr -e cloud, using 2 nodes, 2 shards and replication of 2.
>
> To understand the following, it might be important to know, which ports are used:
> node 1: 8983 (leader for shard1 and shard2)
> node 2: 7574 (no leader at all)
>
>
> In this example i searched for 3 terms in the following order: first on node 1 (8983 - leader) and then on node 2 (7574).
>
> Sample1 (q=test):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>      2)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=17
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample2 (q=foo):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=foo&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=foo&NOW=1512474569299&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=foo&wt=json
>
>    produced logs:
>      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={q=foo&indent=on&wt=json} hits=0 status=0 QTime=13
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample3 (q=test) NOTE- its the same query as in sample1:
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474627254&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>      2)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=13
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample4 (q=baa):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=baa&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=baa&NOW=1512474709460&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=baa&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=baa&indent=on&wt=json} hits=0 status=0 QTime=12
>
>
>
>
> Sorry for this messy logs.
> I'll try to sumarize....
>
> For queries against the node 1, the leading node, i never got those "short logs". just containing what i was querying. Instead i recieve logs containing all these sharding information. Sometimes 2 equivalent ones (see sample 1) and sometimes just one log (sample 2-4). Mentioned that i got different logs for the same query/request (sample1 vs sample3).
>
> For queries against the node 2, not leading anything, i got those "short logs" everytime. In addition to that, i also recievie sometimes an additional log, containing these sharding information (sample 3).
>
>
> My assumptions:
> afaik, the queried shard is choosen randomly, that would explain why i got different amount of logs for same queries/request. But what i everytime the same, is that the "non-leading node" is the only one that returns the logs i want. I tried some other example (that i do not write down here), and i saw the same result. different amount of logs, that look spreaded randomly, but i never got those "short-logs" from the leading node, just from the "non-leading node".
>
>
> So the idea of trying to find the difference between logs is not that suitable, because sometimes they aren't present (facing the leading node).
>
> So the question still reminds: how could i log the incoming request in a proper way?
>
>
> I hope that my problem was clearly described, and someone got an idea whats going on here.

Reply | Threaded
Open this post in threaded view
|

AW: Logging in Solrcloud

Matzdorf, Stefan, Springer SBM DE
first of all, i'm using solr 7.1.0 ...

i took a look into the logfile of solr and see the follwowing 2 log statements for query "test":

4350609 INFO  (qtp1918627686-691) [c:gettingstarted s:shard1 r:core_node5 x:gettingstarted_shard1_replica_n2] o.a.s.c.S.Request [gettingstarted_shard1_replica_n2]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/|http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0

4350615 INFO  (qtp1918627686-20) [c:gettingstarted s:shard2 r:core_node8 x:gettingstarted_shard2_replica_n6] o.a.s.c.S.Request [gettingstarted_shard2_replica_n6]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=7


Both were logged by the org.apache.solr.core.Request - logger (i configured that to log on info level), but there is no information about what kind of request (GET/POST etc) comes in. it just logs what you could see above. do you use a different logger for that? (and with logger in that case i mean the ones you could configre und the logger/level menu in the solr ui, where to choose what you want to log).

Regards
Matze


--
Stefan Matzdorf
Software Engineer
B2X Platform Development

Springer Nature
Heidelberger Platz 3, 14197 Berlin, Germany
T  +4903827975072
[hidden email]
www.springernature.com
---
Springer Nature is one of the world’s leading global research, educational and professional publishers, created in May 2015 through the combination of Nature Publishing Group,
Palgrave Macmillan, Macmillan Education and Springer Science+Business Media.
---
Springer Science+Business Media Deutschland GmbH
Registered Office: Berlin / Amtsgericht Berlin-Charlottenburg, HRB 152987 B
Directors: Derk Haank, Martin Mos, Dr. Ulrich Vest

________________________________________
Von: Walter Underwood <[hidden email]>
Gesendet: Dienstag, 5. Dezember 2017 16:20
An: [hidden email]
Betreff: Re: Logging in Solrcloud

In 6.5.1, the intra-cluster requests are POST, which makes them easy to distinguish in the request logs. Also, the intra-cluster requests go to a specific core instead of to the collection. So we use the request logs and grep out the GET lines.

We are considering fronting every Solr process with a local nginx server. That will allow us to limit concurrent connections. It will also give us a log of just the client requests.

wunder
Walter Underwood
[hidden email]
http://observer.wunderwood.org/  (my blog)


> On Dec 5, 2017, at 4:25 AM, Matzdorf, Stefan, Springer SBM DE <[hidden email]> wrote:
>
> To be more precisely and provide some more details, i tried to simplify the problem by using the Solr-examples that were delivered with the solr....
> So i started bin/solr -e cloud, using 2 nodes, 2 shards and replication of 2.
>
> To understand the following, it might be important to know, which ports are used:
> node 1: 8983 (leader for shard1 and shard2)
> node 2: 7574 (no leader at all)
>
>
> In this example i searched for 3 terms in the following order: first on node 1 (8983 - leader) and then on node 2 (7574).
>
> Sample1 (q=test):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>      2)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=17
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample2 (q=foo):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=foo&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=foo&NOW=1512474569299&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=foo&wt=json
>
>    produced logs:
>      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={q=foo&indent=on&wt=json} hits=0 status=0 QTime=13
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample3 (q=test) NOTE- its the same query as in sample1:
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474627254&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>      2)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=13
>
> ##############################################################################################################################
> ##############################################################################################################################
>
> Sample4 (q=baa):
>    http://localhost:8983/solr/gettingstarted/select?indent=on&q=baa&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=baa&NOW=1512474709460&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
>
>    http://localhost:7574/solr/gettingstarted/select?indent=on&q=baa&wt=json
>
>    produced logs:
>      1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=baa&indent=on&wt=json} hits=0 status=0 QTime=12
>
>
>
>
> Sorry for this messy logs.
> I'll try to sumarize....
>
> For queries against the node 1, the leading node, i never got those "short logs". just containing what i was querying. Instead i recieve logs containing all these sharding information. Sometimes 2 equivalent ones (see sample 1) and sometimes just one log (sample 2-4). Mentioned that i got different logs for the same query/request (sample1 vs sample3).
>
> For queries against the node 2, not leading anything, i got those "short logs" everytime. In addition to that, i also recievie sometimes an additional log, containing these sharding information (sample 3).
>
>
> My assumptions:
> afaik, the queried shard is choosen randomly, that would explain why i got different amount of logs for same queries/request. But what i everytime the same, is that the "non-leading node" is the only one that returns the logs i want. I tried some other example (that i do not write down here), and i saw the same result. different amount of logs, that look spreaded randomly, but i never got those "short-logs" from the leading node, just from the "non-leading node".
>
>
> So the idea of trying to find the difference between logs is not that suitable, because sometimes they aren't present (facing the leading node).
>
> So the question still reminds: how could i log the incoming request in a proper way?
>
>
> I hope that my problem was clearly described, and someone got an idea whats going on here.

Reply | Threaded
Open this post in threaded view
|

Re: Logging in Solrcloud

Walter Underwood
HTTP request log, not solr.log.

This is intra-cluster:

10.98.15.241 - - [29/Oct/2017:23:59:57 +0000] "POST //sc16.prod2.cloud.cheggnet.com:8983/solr/questions_shard4_replica8/auto HTTP/1.1" 200 194

This is from outside (yes, we have long queries):

10.98.15.110 - - [29/Oct/2017:23:59:58 +0000] "GET //solr-cloud.prod2.cheggnet.com:8983/solr/questions/srp?qt=%2Fsrp&q=jack+and+jill+are+maneuvering+a+2800+kg+boat+near+a+dock.+initially+the+boat%27s+position+is+m+and+its+speed+is+1.9+m%2Fs.+as+the+boat+moves+to+position+m%2C+jack+exerts+a+force+n+and+jill+exerts&fq=source%3Atbs&start=0&rows=2&hl=true&hl.q=jack+and+jill+are+maneuvering+a+2800+kg+boat+near+a+dock.+initially+the+boat%27s+position+is+m+and+its+speed+is+1.9+m%2Fs.+as+the+boa

In your case, “gettingstarted_shard1_replica_n2” should mean that is an intra-cluster request. Also, “distrib=false” means it is for a single core.

wunder
Walter Underwood
[hidden email]
http://observer.wunderwood.org/  (my blog)


> On Dec 5, 2017, at 7:38 AM, Matzdorf, Stefan, Springer SBM DE <[hidden email]> wrote:
>
> first of all, i'm using solr 7.1.0 ...
>
> i took a look into the logfile of solr and see the follwowing 2 log statements for query "test":
>
> 4350609 INFO  (qtp1918627686-691) [c:gettingstarted s:shard1 r:core_node5 x:gettingstarted_shard1_replica_n2] o.a.s.c.S.Request [gettingstarted_shard1_replica_n2]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/|http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>
> 4350615 INFO  (qtp1918627686-20) [c:gettingstarted s:shard2 r:core_node8 x:gettingstarted_shard2_replica_n6] o.a.s.c.S.Request [gettingstarted_shard2_replica_n6]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=7
>
>
> Both were logged by the org.apache.solr.core.Request - logger (i configured that to log on info level), but there is no information about what kind of request (GET/POST etc) comes in. it just logs what you could see above. do you use a different logger for that? (and with logger in that case i mean the ones you could configre und the logger/level menu in the solr ui, where to choose what you want to log).
>
> Regards
> Matze
>
>
> --
> Stefan Matzdorf
> Software Engineer
> B2X Platform Development
>
> Springer Nature
> Heidelberger Platz 3, 14197 Berlin, Germany
> T  +4903827975072
> [hidden email]
> www.springernature.com
> ---
> Springer Nature is one of the world’s leading global research, educational and professional publishers, created in May 2015 through the combination of Nature Publishing Group,
> Palgrave Macmillan, Macmillan Education and Springer Science+Business Media.
> ---
> Springer Science+Business Media Deutschland GmbH
> Registered Office: Berlin / Amtsgericht Berlin-Charlottenburg, HRB 152987 B
> Directors: Derk Haank, Martin Mos, Dr. Ulrich Vest
>
> ________________________________________
> Von: Walter Underwood <[hidden email]>
> Gesendet: Dienstag, 5. Dezember 2017 16:20
> An: [hidden email]
> Betreff: Re: Logging in Solrcloud
>
> In 6.5.1, the intra-cluster requests are POST, which makes them easy to distinguish in the request logs. Also, the intra-cluster requests go to a specific core instead of to the collection. So we use the request logs and grep out the GET lines.
>
> We are considering fronting every Solr process with a local nginx server. That will allow us to limit concurrent connections. It will also give us a log of just the client requests.
>
> wunder
> Walter Underwood
> [hidden email]
> http://observer.wunderwood.org/  (my blog)
>
>
>> On Dec 5, 2017, at 4:25 AM, Matzdorf, Stefan, Springer SBM DE <[hidden email]> wrote:
>>
>> To be more precisely and provide some more details, i tried to simplify the problem by using the Solr-examples that were delivered with the solr....
>> So i started bin/solr -e cloud, using 2 nodes, 2 shards and replication of 2.
>>
>> To understand the following, it might be important to know, which ports are used:
>> node 1: 8983 (leader for shard1 and shard2)
>> node 2: 7574 (no leader at all)
>>
>>
>> In this example i searched for 3 terms in the following order: first on node 1 (8983 - leader) and then on node 2 (7574).
>>
>> Sample1 (q=test):
>>   http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>>     2)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474523045&isShard=true&wt=javabin} hits=0 status=0 QTime=1
>>
>>
>>
>>   http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=17
>>
>> ##############################################################################################################################
>> ##############################################################################################################################
>>
>> Sample2 (q=foo):
>>   http://localhost:8983/solr/gettingstarted/select?indent=on&q=foo&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard1_replica_n1/|http://127.0.1.1:8983/solr/gettingstarted_shard1_replica_n2/&rows=10&version=2&q=foo&NOW=1512474569299&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>>
>>
>>
>>   http://localhost:7574/solr/gettingstarted/select?indent=on&q=foo&wt=json
>>
>>   produced logs:
>>     1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={q=foo&indent=on&wt=json} hits=0 status=0 QTime=13
>>
>> ##############################################################################################################################
>> ##############################################################################################################################
>>
>> Sample3 (q=test) NOTE- its the same query as in sample1:
>>   http://localhost:8983/solr/gettingstarted/select?indent=on&q=test&wt=json
>>
>>   produced logs:
>>     1) [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474643732&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>>
>>
>>   http://localhost:7574/solr/gettingstarted/select?indent=on&q=test&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=test&NOW=1512474627254&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>>     2)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=test&indent=on&wt=json} hits=0 status=0 QTime=13
>>
>> ##############################################################################################################################
>> ##############################################################################################################################
>>
>> Sample4 (q=baa):
>>   http://localhost:8983/solr/gettingstarted/select?indent=on&q=baa&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard2_replica_n4]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=4&start=0&fsv=true&shard.url=http://127.0.1.1:7574/solr/gettingstarted_shard2_replica_n4/|http://127.0.1.1:8983/solr/gettingstarted_shard2_replica_n6/&rows=10&version=2&q=baa&NOW=1512474709460&isShard=true&wt=javabin} hits=0 status=0 QTime=0
>>
>>
>>   http://localhost:7574/solr/gettingstarted/select?indent=on&q=baa&wt=json
>>
>>   produced logs:
>>     1)  [gettingstarted_shard1_replica_n1]  webapp=/solr path=/select params={q=baa&indent=on&wt=json} hits=0 status=0 QTime=12
>>
>>
>>
>>
>> Sorry for this messy logs.
>> I'll try to sumarize....
>>
>> For queries against the node 1, the leading node, i never got those "short logs". just containing what i was querying. Instead i recieve logs containing all these sharding information. Sometimes 2 equivalent ones (see sample 1) and sometimes just one log (sample 2-4). Mentioned that i got different logs for the same query/request (sample1 vs sample3).
>>
>> For queries against the node 2, not leading anything, i got those "short logs" everytime. In addition to that, i also recievie sometimes an additional log, containing these sharding information (sample 3).
>>
>>
>> My assumptions:
>> afaik, the queried shard is choosen randomly, that would explain why i got different amount of logs for same queries/request. But what i everytime the same, is that the "non-leading node" is the only one that returns the logs i want. I tried some other example (that i do not write down here), and i saw the same result. different amount of logs, that look spreaded randomly, but i never got those "short-logs" from the leading node, just from the "non-leading node".
>>
>>
>> So the idea of trying to find the difference between logs is not that suitable, because sometimes they aren't present (facing the leading node).
>>
>> So the question still reminds: how could i log the incoming request in a proper way?
>>
>>
>> I hope that my problem was clearly described, and someone got an idea whats going on here.
>