[ https://issues.apache.org/jira/browse/SOLR-16910?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17752513#comment-17752513 ]
David Smiley commented on SOLR-16910: ------------------------------------- {quote} * new class wouldn't do any actual logging – would just put info about adds/dels in {{rsp.toLog}}{quote} FWIW this is what we do at work. We don't use the stock LogUpdateProcessorFactory, we have our own which adds to rsp.toLog and thus has normal looking request logs. > 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