Solr
  1. Solr
  2. SOLR-2124

SEVERE exceptions are being logged for expected PingRequestHandler SERVICE_UNAVAILABLE exceptions

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.6, 4.0-ALPHA
    • Component/s: None
    • Labels:
      None

      Description

      As reported by a user, if you use the PingRequestHandler, and the corrisponding helthcheck file doesn't exist (and expected situation when a server is out of rotation) Solr is logging a SEVERE error...

      SEVERE: org.apache.solr.common.SolrException: Service disabled
      	at org.apache.solr.handler.PingRequestHandler.handleRequestBody(PingRequestHandler.java:48)
      	at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:131)
      	at org.apache.solr.core.SolrCore.execute(SolrCore.java:1324)
      	at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:337)
      	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:240)
      	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
      	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
      	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
      	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
      	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
      	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
      	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
      	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
      	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
      	at org.mortbay.jetty.Server.handle(Server.java:326)
      	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
      	at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:923)
      	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:547)
      	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
      	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
      	at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228)
      	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
      

      This is in spite of hte fact that PingRequestHandler explicitly sets the "alreadyLogged" boolean to true in the SolrException constructor.

        Issue Links

          Activity

          Hide
          Hoss Man added a comment -

          At first glance, this seems like a fundemental problem with how the "logged" property of SolrException is used ... logOnce is hte only method that ever tests it, the other log methods blindly set it to true and proceed with logging.

          if this is intentional, then i suspect there are lots of places in the code that are using "log" when they are suppose to be using "logOnce"

          (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors)

          Show
          Hoss Man added a comment - At first glance, this seems like a fundemental problem with how the "logged" property of SolrException is used ... logOnce is hte only method that ever tests it, the other log methods blindly set it to true and proceed with logging. if this is intentional, then i suspect there are lots of places in the code that are using "log" when they are suppose to be using "logOnce" (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors)
          Hide
          Shawn Heisey added a comment -

          I looked at the 1.4.1 source, since that's what I am using at the moment. I changed one line in RequestHandlerBase.java. Original line:

          SolrException.log(SolrCore.log,e);

          New line:

          SolrException.logOnce(SolrCore.log,null,e);

          The modified 1.4.1 source successfully compiled and passed all junit tests. It'll take me a while to get to the point where I can try it out to see whether it actually makes things better. I'm not qualified to check whether this change will cause problems elsewhere. This change does not address Hoss's parenthetical comment regarding the logged property defaulting to true.

          Show
          Shawn Heisey added a comment - I looked at the 1.4.1 source, since that's what I am using at the moment. I changed one line in RequestHandlerBase.java. Original line: SolrException.log(SolrCore.log,e); New line: SolrException.logOnce(SolrCore.log,null,e); The modified 1.4.1 source successfully compiled and passed all junit tests. It'll take me a while to get to the point where I can try it out to see whether it actually makes things better. I'm not qualified to check whether this change will cause problems elsewhere. This change does not address Hoss's parenthetical comment regarding the logged property defaulting to true.
          Hide
          Yonik Seeley added a comment -

          if this is intentional, then i suspect there are lots of places in the code that are using "log" when they are suppose to be using "logOnce"

          Yep, probably so. Last time I audited the exception logging for that was so long ago that I I think I worked at CNET

          (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors)
          Hmmm, yeah. Wish I could remember why that was.
          If we change, we should probably check out all of the places that use those constructors too.

          Show
          Yonik Seeley added a comment - if this is intentional, then i suspect there are lots of places in the code that are using "log" when they are suppose to be using "logOnce" Yep, probably so. Last time I audited the exception logging for that was so long ago that I I think I worked at CNET (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors) Hmmm, yeah. Wish I could remember why that was. If we change, we should probably check out all of the places that use those constructors too.
          Hide
          Shawn Heisey added a comment -

          I was able to test it sooner than I expected. I am now getting no log at all when checking the ping handler on a disabled core, which I suspect is not a desirable effect, and probably due to the logged property defaulting to true as Hoss mentioned.

          Show
          Shawn Heisey added a comment - I was able to test it sooner than I expected. I am now getting no log at all when checking the ping handler on a disabled core, which I suspect is not a desirable effect, and probably due to the logged property defaulting to true as Hoss mentioned.
          Hide
          Yonik Seeley added a comment -

          (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors)

          It looks like it always defaults to true if it takes a Throwable.
          I guess the original idea was probably that if you caught a Throwable, you should either log it right there (as opposed to logging the SolrException), or not at all.

          Show
          Yonik Seeley added a comment - (It also makes no sense to me that the "logged" property is defaulted to "true" in several constructors) It looks like it always defaults to true if it takes a Throwable. I guess the original idea was probably that if you caught a Throwable, you should either log it right there (as opposed to logging the SolrException), or not at all.
          Hide
          Shawn Heisey added a comment -

          I spent a while trying to work out the changes required to use logOnce and have it work as expected, got overwhelmed and lost. Then I started with a fresh source tarball and tried to figure out how to just get it to log an error instead of throwing an exception. I lack the necessary java skills to do something so basic.

          Show
          Shawn Heisey added a comment - I spent a while trying to work out the changes required to use logOnce and have it work as expected, got overwhelmed and lost. Then I started with a fresh source tarball and tried to figure out how to just get it to log an error instead of throwing an exception. I lack the necessary java skills to do something so basic.
          Hide
          Robert Muir added a comment -
          Show
          Robert Muir added a comment - Moving out all unassigned issues set to 3.1 per this email: http://www.lucidimagination.com/search/document/f026cc56081b5a51/unassigned_jira_issues_set_for_3_1
          Hide
          Robert Muir added a comment -

          Bulk move 3.2 -> 3.3

          Show
          Robert Muir added a comment - Bulk move 3.2 -> 3.3
          Hide
          Robert Muir added a comment -

          3.4 -> 3.5

          Show
          Robert Muir added a comment - 3.4 -> 3.5
          Hide
          Erick Erickson added a comment -

          A lot has changed since this was submitted, see: SOLR-2191 and associated. Is this still an issue? I confess I'm not quite sure how to reproduce it to test (hint, hint)....

          Show
          Erick Erickson added a comment - A lot has changed since this was submitted, see: SOLR-2191 and associated. Is this still an issue? I confess I'm not quite sure how to reproduce it to test (hint, hint)....
          Hide
          James Dyer added a comment -

          I think this is still a problem. I have a snapshot from 1/31 (post-2191 and its children) and it still logs a whole stack trace every time the load balancer pings it, if the "service-enabled" file is missing. This is a pretty big annoyance for me because I often use a "live", load-balanced dev environment to test new versions with the testing node taken "out" using this ping feature. If nobody else does anything, I'll likely be annoyed enough to fix it eventually.

          Show
          James Dyer added a comment - I think this is still a problem. I have a snapshot from 1/31 (post-2191 and its children) and it still logs a whole stack trace every time the load balancer pings it, if the "service-enabled" file is missing. This is a pretty big annoyance for me because I often use a "live", load-balanced dev environment to test new versions with the testing node taken "out" using this ping feature. If nobody else does anything, I'll likely be annoyed enough to fix it eventually.
          Hide
          Erick Erickson added a comment -

          James:

          I'll let you get to it then when you get annoyed <G>....

          Do note that the whole logOnce stuff doesn't exist any more in trunk, FWIW....

          Show
          Erick Erickson added a comment - James: I'll let you get to it then when you get annoyed <G>.... Do note that the whole logOnce stuff doesn't exist any more in trunk, FWIW....
          Hide
          James Dyer added a comment -

          Patch changes SolrException to not log the exception if its 503/"Service Unavailable". In all cases this is used, the 503 SE is thrown intentionally. That is, its really not a Runtime-style exception at all. There is nothing to debug and a stack trace is no going to be helpful.

          For PingRequestHandler, this is what it logs AFTER the patch:

          12:33:45,836 INFO [SolrCore] [] webapp=/Solr_Trunk path=/admin/ping params={} status=503 QTime=0

          (compare with the full stack trace in the Description)

          I will commit shortly if nobody objects.

          Show
          James Dyer added a comment - Patch changes SolrException to not log the exception if its 503/"Service Unavailable". In all cases this is used, the 503 SE is thrown intentionally. That is, its really not a Runtime-style exception at all. There is nothing to debug and a stack trace is no going to be helpful. For PingRequestHandler, this is what it logs AFTER the patch: 12:33:45,836 INFO [SolrCore] [] webapp=/Solr_Trunk path=/admin/ping params={} status=503 QTime=0 (compare with the full stack trace in the Description) I will commit shortly if nobody objects.
          Hide
          Shawn Heisey added a comment -

          Thank you, James! I am really looking forward to 3.6.

          Show
          Shawn Heisey added a comment - Thank you, James! I am really looking forward to 3.6.
          Hide
          James Dyer added a comment -

          committed.

          Trunk: r1302970
          Branch_3x: r1303037

          Show
          James Dyer added a comment - committed. Trunk: r1302970 Branch_3x: r1303037

            People

            • Assignee:
              James Dyer
              Reporter:
              Hoss Man
            • Votes:
              1 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development