[
https://issues.apache.org/jira/browse/SOLR-16910?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17748353#comment-17748353
]
Chris M. Hostetter commented on SOLR-16910:
-------------------------------------------
I don't have a particular firm grasp on what the "Right" behavior should be for
{{LogUpdateProcessorFactory}} – particularly in a way that doesn't break too
many existing expectations about who/what/where/how-often various things get
logged – I just know that these two statements make my skin crawl:
* changing the {{LogUpdateProcessorFactory}} level changes whether or not
{{SolrCore.Request}} logs some requests
* changing the {{LogUpdateProcessorFactory}} level changes the _format_ of the
{{LogUpdateProcessorFactory}} WARN level logs
----
Some off the cuff, pie in the sky, ideas on how we might be able to make this
whole situation less insane and offer some semblance of back compat support:
* Rip out all of {{LogUpdateProcessorFactory}} 's logic to clear {{rsp.toLog}}
** And change {{LogUpdateProcessorFactory}} to set an MDC value to indicate
if/when it's (already) logged a request
** By Default, {{LogUpdateProcessorFactory}} and {{SolrCore.Request}} will
both log the same requests
*** But we can include a commented out example in {{log4j2.xml}} showing how
to filter out those messages from {{SolrCore.Request}}
* Rip out all of {{LogUpdateProcessorFactory}} 's logic to clear {{rsp.toLog}}
** And change {{SolrCore}} to set MDC values on every request to indicate the
"path" (and Category) of the request handler
** By Default, {{LogUpdateProcessorFactory}} and {{SolrCore.Request}} will
both log the same requests
*** But we can include a commented out example in {{log4j2.xml}} showing how
to filter out those messages from {{SolrCore.Request}}
* Deprecate {{LogUpdateProcessorFactory}}
** Replace it in default update chains (conditional on
{{{}luceneMatchVersion{}}}) with a new {{LogSummaryUpdateProcessorFactory}}
*** new class wouldn't do any actual logging – would just put info about
adds/dels in {{rsp.toLog}}
** Existing {{SolrCore.Request}} code will log that extra info if
{{LogSummaryUpdateProcessorFactory}} is used
*** And if {{LogUpdateProcessorFactory}} is still used instead, the current
insane behavior will continue
> 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
> Priority: Major
>
> 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
