[jira] [Updated] (SOLR-16910) Adjusting LogUpdateProcessorFactory's log level has side effects on SolrCore logging and changes "slowUpdateThresholdMillis" formatting

["ASF GitHub Bot (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/SOLR-16910?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

ASF GitHub Bot updated SOLR-16910:
----------------------------------
    Labels: pull-request-available  (was: )

> 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
>            Reporter: Chris M. Hostetter
>            Priority: Major
>              Labels: pull-request-available
>          Time Spent: 10m
>  Remaining Estimate: 0h
>
> 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-unsubscribe@solr.apache.org
For additional commands, e-mail: issues-help@solr.apache.org