Chris M. Hostetter created SOLR-16910:
-----------------------------------------
Summary: Adjusting LogUpdateProcessorFactory's log level has side
effects on SolrCore logging and changes "slowUpdateThresholdMillis" formatting
Key: SOLR-16910
URL: https://issues.apache.org/jira/browse/SOLR-16910
Project: Solr
Issue Type: Bug
Security Level: Public (Default Security Level. Issues are Public)
Reporter: Chris M. Hostetter
The logic in {{LogUpdateProcessorFactory.finish()}} when doing "INFO" level
logging is weird.
It has some non-intuitive side effects on:
* SolrCore's {{Request}} logger
* the output format of it's own {{slowUpdateThresholdMillis}} logging.
Current logic (psuedocode)...
{code:java}
if (my logging level is at least INFO):
log.info( rsp.toLog + (summary of adds and deletes processed) + elapsed time
)
clear rsp.toLog
if (my logging level is at least WARN):
if ( elapsed time > slowUpdateThresholdMillis ):
log.warn( "slow: " + rsp.toLog + (summary of adds and deletes processed) +
elapsed time )
clear rsp.toLog
{code}
...the crux of the logic living in
{{LogUpdateProcessorFactory.getLogStringAndClearRspToLog()}} which handles the
formatting of the log messages and clearing {{{}rsp.toLog{}}}.
When {{rsp.toLog}} is empty, SolrCore's {{Request}} logger (intentionally) does
*{*}NOT{*}* log the request.
If you have {{INFO}} level logging configured globally, and you don't configure
{{{}slowUpdateThresholdMillis{}}}, (ie: the solr default behavior) then the
behavior of {{LogUpdateProcessorFactory}} is only slightly weird:
* {{LogUpdateProcessorFactory}} INFO logs "update" requests with added context
about adds/deletes
** Unless there was an exception thrown during the updates (before
{{finish()}} was called) - then it logs nothing
* SolrCore's {{Request}} logger INFO logs any request that
{{LogUpdateProcessorFactory}} doesn't
** (ie: non update requests, or update requests that threw exceptions)
(I'm guessing most solr devs are just use to this long standing default
beahvior and don't really think about why SolrCore doesn't log {{/update}}
requests ...or even notice that it _does_ log {{/update}} requests that threw
an exception)
If you have {{INFO}} level logging configured globally, and you turn on
{{{}slowUpdateThresholdMillis{}}}, the behavior of
{{LogUpdateProcessorFactory}} is a _little_ weird:
* {{LogUpdateProcessorFactory}} INFO logs "update" requests with added context
about adds/deletes
** {{LogUpdateProcessorFactory}} WARN logs any "slow" update requests with
added context about adds/deletes
*** _*BUT*_ ... w/o the standard request info (webapp, path, request params,
etc...)
** the "QTime" logged for each request can be _different_ between the INFO
logging and the WARN logging
* SolrCore's {{Request}} logger INFO logs any request that
{{LogUpdateProcessorFactory}} doesn't
** (ie: non update requests, or update requests that threw exceptions)
If you customize the logging levels for various loggers, things get _*REALLY*_
weird...
* {{LogUpdateProcessorFactory=OFF}} + {{SolrCore.Request=INFO}}
** Now SolrCore's {{Request}} logger _does_ log updates just like other types
of requests
* {{LogUpdateProcessorFactory=WARN}} + {{slowUpdateThresholdMillis}} +
{{SolrCore.Request=INFO}}
** Now SolrCore's {{Request}} logger _does_ log updates just like other types
of requests
*** And even SolrCore's {{SlowRequest}} logger may log it (if it's slow)
** _*UNLESS...*_ the request is slower then {{slowUpdateThresholdMillis}} ...
*** In which case {{LogUpdateProcessorFactory}} WARN logs it *WITH* the
standard request info (webapp, path, request params, etc...)
*** *But* these "slow" queries don't get logged by SolrCore's {{{{Request}}}}
or {{SlowRequest}} loggers
----
Example scenarios that can arise from these combinations, that might cause you
to think you're losing your mind (one of these may - or may not - have happened
to me)
* You start with {{LogUpdateProcessorFactory=OFF}} + {{SolrCore.Request=INFO}}
(with some {{slowQueryThresholdMillis}} configured)
** You change {{LogUpdateProcessorFactory=INFO}} because you want to see the
add/delete details of some of the {{/update}} requests in your slow query log
** Now you get {{LogUpdateProcessorFactory}} logging of your updates - but for
some reason they stop showing up in your normal and/or slow query logs ???
* You start with {{ROOT=INFO}}
** You feel like your logs are too noisy
*** in particular you don't need to see all {{LogUpdateProcessorFactory}}
logging of updates, because you really only care about the "queries" being
logged by {{SolrCore.Request}}
** So you change to {{ROOT=WARN}} + {{SolrCore.Request=INFO}}
*** Now for some reason {{SolrCore.Request}} is suddenly logging update
requests it wasn't logging before ???
* You start with {{ROOT=WARN}} and have {{slowUpdateThresholdMillis}}
configured
** You are happy with the format of the {{slow: ...}} WARN messages you get
from {{LogUpdateProcessorFactory}} and an automated tool that parses those logs
to run a report
** You need to do some debugging, so you temporarily enable {{ROOT=INFO}}
*** now for some reason your {{slow: ...}} WARN messages are in a different
format that breaks your log parsing tool
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscr...@solr.apache.org
For additional commands, e-mail: issues-h...@solr.apache.org
