mmiklavc edited a comment on issue #1475: METRON-2197 Add debugging info output for Solr queries URL: https://github.com/apache/metron/pull/1475#issuecomment-517376520 @ottobackwards I tinkered with a reformat. Here's what it looks like if I merge them into a single debug statement ``` 2019-08-01 11:07:06 DEBUG SolrSearchDao:112 - Solr query string: ?start=0&rows=10&q=ip_src_addr%3A192.168.1.9&debugQuery=true&sort=timestamp+desc&fl=ip_src_addr&collection=bro%2Csnort&_stateVer_=bro%3A4%7Csnort%3A3 Solr query debug map: {track={rid=127.0.0.1-snort_shard1_replica1-1564679226940-11,EXECUTE_QUERY={http://127.0.0.1:8983/solr/snort_shard1_replica1/={QTime=1,ElapsedTime=4,RequestPurpose=GET_TOP_IDS,NumFound=0,Response={responseHeader={zkConnected=true,status=0,QTime=1,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/snort_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226940-11,version=2,q=ip_src_addr:192.168.1.9,requestPurpose=GET_TOP_IDS,NOW=1564679226940,isShard=true,wt=javabin,debugQuery=false}},response={numFound=0,start=0,docs=[]},sort_values={timestamp=[]},debug={timing={time=1.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}},http://127.0.0.1:8983/solr/bro_shard1_replica1/={QTime=1,ElapsedTime=4,RequestPurpose=GET_TOP_IDS,NumFound=0,Response={responseHeader={zkConnected=true,status=0,QTime=1,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/bro_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226940-11,version=2,q=ip_src_addr:192.168.1.9,requestPurpose=GET_TOP_IDS,NOW=1564679226940,isShard=true,wt=javabin,debugQuery=false}},response={numFound=0,start=0,docs=[]},sort_values={timestamp=[]},debug={timing={time=1.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}}}}, timing={time=2.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}, rawquerystring=ip_src_addr:192.168.1.9, querystring=ip_src_addr:192.168.1.9, parsedquery=ip_src_addr:192.168.1.9, parsedquery_toString=ip_src_addr:192.168.1.9, QParser=LuceneQParser, explain={}} Solr query elapsed time: 9 Solr query Q time: 6 ... 2019-08-01 11:07:06 DEBUG SolrSearchDao:112 - Solr query string: ?start=0&rows=10&q=*&debugQuery=true&sort=timestamp+desc&fl=*&collection=bro%2Csnort&_stateVer_=bro%3A4%7Csnort%3A3 Solr query debug map: {track={rid=127.0.0.1-snort_shard1_replica1-1564679226954-12,EXECUTE_QUERY={http://127.0.0.1:8983/solr/bro_shard1_replica1/={QTime=0,ElapsedTime=4,RequestPurpose=GET_TOP_IDS,NumFound=5,Response={responseHeader={zkConnected=true,status=0,QTime=0,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/bro_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226954-12,version=2,q=*,requestPurpose=GET_TOP_IDS,NOW=1564679226954,isShard=true,wt=javabin,debugQuery=false}},response={numFound=5,start=0,docs=[SolrDocument{guid=bro_5}, SolrDocument{guid=bro_4}, SolrDocument{guid=bro_3}, SolrDocument{guid=bro_2}, SolrDocument{guid=bro_1}]},sort_values={timestamp=[5, 4, 3, 2, 1]},debug={timing={time=0.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}},http://127.0.0.1:8983/solr/snort_shard1_replica1/={QTime=0,ElapsedTime=4,RequestPurpose=GET_TOP_IDS,NumFound=5,Response={responseHeader={zkConnected=true,status=0,QTime=0,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/snort_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226954-12,version=2,q=*,requestPurpose=GET_TOP_IDS,NOW=1564679226954,isShard=true,wt=javabin,debugQuery=false}},response={numFound=5,start=0,docs=[SolrDocument{guid=snort_5}, SolrDocument{guid=snort_4}, SolrDocument{guid=snort_3}, SolrDocument{guid=snort_2}, SolrDocument{guid=snort_1}]},sort_values={timestamp=[10, 9, 8, 7, 6]},debug={timing={time=0.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}}},GET_FIELDS={http://127.0.0.1:8983/solr/bro_shard1_replica1/={QTime=1,ElapsedTime=5,RequestPurpose=GET_FIELDS,GET_DEBUG,NumFound=5,Response={responseHeader={zkConnected=true,status=0,QTime=1,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[timing, track],fl=*,shards.purpose=320,start=0,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/bro_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226954-12,version=2,q=*,requestPurpose=GET_FIELDS,GET_DEBUG,NOW=1564679226954,ids=bro_2,bro_3,bro_1,bro_4,bro_5,isShard=true,wt=javabin,debugQuery=true}},response={numFound=5,start=0,docs=[SolrDocument{long_field=20000, ip_src_port=8009, method=bro data 2, latitude=48.0001, location_point=48.5839,7.7455, guid=bro_2, is_alert=false, ip_src_addr=192.168.1.2, ttl=data 2, source.type=bro, timestamp=2, _version_=1640685083858829312}, SolrDocument{long_field=10000, ip_src_port=8008, method=bro data 3, latitude=48.5839, location_point=50.0,7.7455, guid=bro_3, is_alert=true, ip_src_addr=192.168.1.3, ttl=data 3, source.type=bro, timestamp=3, _version_=1640685083859877888}, SolrDocument{long_field=10000, ip_src_port=8010, method=bro data 1, latitude=48.5839, location_point=48.5839,7.7455, guid=bro_1, is_alert=true, ip_src_addr=192.168.1.1, ttl=data 1, source.type=bro, timestamp=1, _version_=1640685083763408896}, SolrDocument{long_field=10000, ip_src_port=8007, method=bro data 4, latitude=48.5839, location_point=48.5839,7.7455, guid=bro_4, is_alert=true, ip_src_addr=192.168.1.4, ttl=data 4, source.type=bro, timestamp=4, _version_=1640685083860926464}, SolrDocument{long_field=10000, ip_src_port=8006, method=bro data 5, latitude=48.5839, location_point=48.5839,7.7455, guid=bro_5, is_alert=true, ip_src_addr=192.168.1.5, ttl=data 5, source.type=bro, timestamp=5, _version_=1640685083863023616}]},debug={rawquerystring=*,querystring=*,parsedquery=MatchAllDocsQuery(*:*),parsedquery_toString=*:*,explain={bro_2= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_3= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_1= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_4= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_5= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm },QParser=LuceneQParser,timing={time=1.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}},http://127.0.0.1:8983/solr/snort_shard1_replica1/={QTime=1,ElapsedTime=5,RequestPurpose=GET_FIELDS,GET_DEBUG,NumFound=5,Response={responseHeader={zkConnected=true,status=0,QTime=1,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[timing, track],fl=*,shards.purpose=320,start=0,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/snort_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564679226954-12,version=2,q=*,requestPurpose=GET_FIELDS,GET_DEBUG,NOW=1564679226954,ids=snort_4,snort_3,snort_2,snort_1,snort_5,isShard=true,wt=javabin,debugQuery=true}},response={numFound=5,start=0,docs=[SolrDocument{long_field=20000, ip_src_port=8002, latitude=48.0001, location_point=48.5839,7.7455, guid=snort_4, is_alert=true, ip_src_addr=192.168.1.1, sig_generator=sig_generator 4, ttl=4, source.type=snort, timestamp=9, _version_=1640685084007727104}, SolrDocument{long_field=10000, ip_src_port=8003, latitude=48.5839, location_point=48.5839,7.7455, guid=snort_3, is_alert=false, ip_src_addr=192.168.1.7, sig_generator=sig_generator 3, ttl=3, source.type=snort, timestamp=8, _version_=1640685084006678528}, SolrDocument{long_field=10000, threat:triage:score=20.0, latitude=48.5839, is_alert=true, ttl=2, source.type=snort, ip_src_port=8004, location_point=48.5839,7.7455, guid=snort_2, ip_src_addr=192.168.1.1, sig_generator=sig_generator 2, timestamp=7, _version_=1640685084004581376}, SolrDocument{long_field=10000, threat:triage:score=10.0, latitude=48.5839, is_alert=false, ttl=1, source.type=snort, ip_src_port=8005, location_point=50.0,7.7455, guid=snort_1, ip_src_addr=192.168.1.6, sig_generator=sig_generator 1, timestamp=6, _version_=1640685084000387072}, SolrDocument{long_field=10000, ip_src_port=8001, latitude=48.5839, location_point=48.5839,7.7455, guid=snort_5, is_alert=false, ip_src_addr=192.168.1.8, sig_generator=sig_generator 5, ttl=5, source.type=snort, timestamp=10, _version_=1640685084007727105}]},debug={rawquerystring=*,querystring=*,parsedquery=MatchAllDocsQuery(*:*),parsedquery_toString=*:*,explain={snort_4= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_3= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_2= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_1= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_5= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm },QParser=LuceneQParser,timing={time=1.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}}}}, timing={time=2.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}, rawquerystring=*, querystring=*, parsedquery=MatchAllDocsQuery(*:*), parsedquery_toString=*:*, QParser=LuceneQParser, explain={snort_5= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_4= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_3= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_2= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,snort_1= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_5= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_4= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_3= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_2= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm ,bro_1= 1.0 = *:*, product of: 1.0 = boost 1.0 = queryNorm }} Solr query elapsed time: 15 Solr query Q time: 11 ``` The original looked like this. To your point, those multiple lines could get interwoven with other searches going on simultaneously. I like the joined version better. ``` 2019-07-31 13:11:03 DEBUG SolrSearchDao:113 - Solr query string: ?start=0&rows=10&q=ip_src_addr%3A192.168.1.9&debugQuery=true&sort=timestamp+desc&fl=ip_src_addr&collection=bro%2Csnort&_stateVer_=bro%3A4%7Csnort%3A3 2019-07-31 13:11:03 DEBUG SolrSearchDao:114 - Solr query debug map: {track={rid=127.0.0.1-snort_shard1_replica1-1564600263731-11,EXECUTE_QUERY={http://127.0.0.1:8983/solr/bro_shard1_replica1/={QTime=12,ElapsedTime=15,RequestPurpose=GET_TOP_IDS,NumFound=0,Response={responseHeader={zkConnected=true,status=0,QTime=12,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/bro_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564600263731-11,version=2,q=ip_src_addr:192.168.1.9,requestPurpose=GET_TOP_IDS,NOW=1564600263730,isShard=true,wt=javabin,debugQuery=false}},response={numFound=0,start=0,docs=[]},sort_values={timestamp=[]},debug={timing={time=12.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}},http://127.0.0.1:8983/solr/snort_shard1_replica1/={QTime=12,ElapsedTime=15,RequestPurpose=GET_TOP_IDS,NumFound=0,Response={responseHeader={zkConnected=true,status=0,QTime=12,params={df=text,distrib=false,_stateVer_=bro:4|snort:3,preferLocalShards=false,debug=[false, timing, track],fl=guid,shards.purpose=4,start=0,fsv=true,sort=timestamp desc,collection=bro,snort,shard.url=http://127.0.0.1:8983/solr/snort_shard1_replica1/,rows=10,rid=127.0.0.1-snort_shard1_replica1-1564600263731-11,version=2,q=ip_src_addr:192.168.1.9,requestPurpose=GET_TOP_IDS,NOW=1564600263730,isShard=true,wt=javabin,debugQuery=false}},response={numFound=0,start=0,docs=[]},sort_values={timestamp=[]},debug={timing={time=12.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}}}}}}, timing={time=24.0,prepare={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}},process={time=0.0,query={time=0.0},facet={time=0.0},facet_module={time=0.0},mlt={time=0.0},highlight={time=0.0},stats={time=0.0},expand={time=0.0},terms={time=0.0},debug={time=0.0}}}, rawquerystring=ip_src_addr:192.168.1.9, querystring=ip_src_addr:192.168.1.9, parsedquery=ip_src_addr:192.168.1.9, parsedquery_toString=ip_src_addr:192.168.1.9, QParser=LuceneQParser, explain={}} 2019-07-31 13:11:03 DEBUG SolrSearchDao:115 - Solr query elapsed time: 20 2019-07-31 13:11:03 DEBUG SolrSearchDao:116 - Solr query Q time: 16 ```
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: us...@infra.apache.org With regards, Apache Git Services
