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