Solr
  1. Solr
  2. SOLR-4019

Service Unavailable errors not being logged

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 4.1, 6.0
    • Component/s: None
    • Labels:
      None

      Description

      Due to changes introduced in SOLR-2124, Service Unavailable (503) errors intentionally not logged. This was introduced to avoid the PingRequestHandler to generate exceptions in logs for requests that are not really exceptions for Solr, see http://www.gossamer-threads.com/lists/lucene/java-dev/171982 The problem with this now is that in some cases (like when using SolrCloud), 503 are critic problem and an exception should be logged.
      Per hoss comment:

      The crux of the problem historically, and how we got into the weird
      situation with the Ping handler is that we wnat to return to the client
      the 503, so we threw an exception that would propogate up and result in
      SolrDispatchFilter returning the 503 – but in the meantime we had to jump
      through a bunch of hoops to deal with the logging because for solr it's
      not really an error and we shouldn't freak out about logging. (ie: we want
      the client to know there is an 503 error, but on the server we don't
      relaly care.

      and the hoops we've jumped through for logging are now hurting us in a
      differnet situation where the 503 really is a serious problem.

      We have a similar situation in the ShowFileHandler where we want the
      client to ge a 404 error, so we throw a SolrException witha 404 error,
      but as a result Solr logs loud and ugly that a 404 error happened.

      I think the cleanest way to deal with this now, would be to change
      PingRequestHandler and ShowFileRequestHandler so that instead of
      throwing a SolrException, their handleRequest methods just construct a
      new SolrException with the appropraite status code, put that exception in
      the SolrQueryResponse, and then return. I think that would ypass
      the loud conspicous logging that currently happens when exceptions are
      thrown (and would let us remove the "ignore SERVICE_UNAVAILABLE
      exceptions" kludge that is huring us in SolrCloud so those exceptions
      would be logged loud and conspicuously)

      This type of solution is something that we might have been able to do
      along time ago except that it would have been complicated because of the
      different code paths arround writting successful output using hte response
      writers vs delegating error responses to the servlet container – but now
      it doesn't matter, we use the response writters either way, so i think
      itwould be relatively striaght forward (although there may be some
      vestigal "oh no, we found an exception, we must log it" logic in the
      request dispatcher that might need to be tweaked to only do that if the
      exception is thrown and not just an object in the response)

      1. SOLR-4019.patch
        4 kB
        Tomás Fernández Löbbe
      2. SOLR-4019.patch
        2 kB
        Tomás Fernández Löbbe

        Issue Links

          Activity

          Hide
          Tomás Fernández Löbbe added a comment -

          Here is an initial patch. I would like to test/review it more as this could impact many places.
          It does sound to me that in most cases you would want Service Unavailable exceptions to be logged, the "ping" command is a specific case where you wouldn't.
          I couldn't find 503 exceptions in ShowFileRequestHandler.
          I intentionally left some "Service Unavailable" exceptions being throw in the PingRequestHandler in cases where I think ARE unexpected errors (like when trying to enable/disable without a healthcheck file defined).

          Show
          Tomás Fernández Löbbe added a comment - Here is an initial patch. I would like to test/review it more as this could impact many places. It does sound to me that in most cases you would want Service Unavailable exceptions to be logged, the "ping" command is a specific case where you wouldn't. I couldn't find 503 exceptions in ShowFileRequestHandler. I intentionally left some "Service Unavailable" exceptions being throw in the PingRequestHandler in cases where I think ARE unexpected errors (like when trying to enable/disable without a healthcheck file defined).
          Hide
          Hoss Man added a comment -

          I couldn't find 503 exceptions in ShowFileRequestHandler.

          the analogous situation i was refering to in ShowFileRequestHandler was when it returns 404s

          Show
          Hoss Man added a comment - I couldn't find 503 exceptions in ShowFileRequestHandler. the analogous situation i was refering to in ShowFileRequestHandler was when it returns 404s
          Hide
          Tomás Fernández Löbbe added a comment -

          Updated patch. In the ShowFileRequestHandler I also avoid throwing the exception for the cases where the file has been intentionally hidden.
          I also think there is a bug in the log(Logger log, String msg, Throwable e) method of the SolrException. The code is:

            public static void log(Logger log, String msg, Throwable e) {
              if (e instanceof SolrException
                  && ((SolrException) e).code() == ErrorCode.SERVICE_UNAVAILABLE.code) {
                log(log, msg);
              }
              String stackTrace = msg + ':' + toStr(e);
              String ignore = doIgnore(e, stackTrace);
              if (ignore != null) {
                log.info(ignore);
                return;
              }
              log.error(stackTrace);
            }
          
            public static void log(Logger log, String msg) {
              String stackTrace = msg;
              String ignore = doIgnore(null, stackTrace);
              if (ignore != null) {
                log.info(ignore);
                return;
              }
              log.error(stackTrace);
            }
          

          It looks like exceptions that are logged with this method and have the code 503 are going to be logged twice (the second time with the stacktrace) where the intention was to only log the message. This patch also removes that double logging.

          Show
          Tomás Fernández Löbbe added a comment - Updated patch. In the ShowFileRequestHandler I also avoid throwing the exception for the cases where the file has been intentionally hidden. I also think there is a bug in the log(Logger log, String msg, Throwable e) method of the SolrException. The code is: public static void log(Logger log, String msg, Throwable e) { if (e instanceof SolrException && ((SolrException) e).code() == ErrorCode.SERVICE_UNAVAILABLE.code) { log(log, msg); } String stackTrace = msg + ':' + toStr(e); String ignore = doIgnore(e, stackTrace); if (ignore != null ) { log.info(ignore); return ; } log.error(stackTrace); } public static void log(Logger log, String msg) { String stackTrace = msg; String ignore = doIgnore( null , stackTrace); if (ignore != null ) { log.info(ignore); return ; } log.error(stackTrace); } It looks like exceptions that are logged with this method and have the code 503 are going to be logged twice (the second time with the stacktrace) where the intention was to only log the message. This patch also removes that double logging.
          Hide
          James Dyer added a comment -

          Tomas, your patch keeps PingRequestHandler quiet, Kludge-free. I appreciate your pointing out SolrQueryResponse#setException, a handy method I wasn't aware of. Your change to ShowFileRequestHandler, while unrelated, seems reasonable. I would think that any other logging tweaks like these can be handled as they are found, right? If you are satisfied enough for now, I will go ahead and commit this.

          Show
          James Dyer added a comment - Tomas, your patch keeps PingRequestHandler quiet, Kludge-free. I appreciate your pointing out SolrQueryResponse#setException, a handy method I wasn't aware of. Your change to ShowFileRequestHandler, while unrelated, seems reasonable. I would think that any other logging tweaks like these can be handled as they are found, right? If you are satisfied enough for now, I will go ahead and commit this.
          Hide
          Tomás Fernández Löbbe added a comment -

          Your change to ShowFileRequestHandler, while unrelated, seems reasonable.

          yes, maybe this should have been implemented on a different issue.

          I would think that any other logging tweaks like these can be handled as they are found, right?

          Agreed.

          Should I create a patch for 4.x too?

          Show
          Tomás Fernández Löbbe added a comment - Your change to ShowFileRequestHandler, while unrelated, seems reasonable. yes, maybe this should have been implemented on a different issue. I would think that any other logging tweaks like these can be handled as they are found, right? Agreed. Should I create a patch for 4.x too?
          Hide
          James Dyer added a comment -

          I think svn will merge this just fine so we don't need a 4.x patch.

          Show
          James Dyer added a comment - I think svn will merge this just fine so we don't need a 4.x patch.
          Hide
          James Dyer added a comment -

          committed.

          Trunk: r1405893
          4x: r1405894

          Show
          James Dyer added a comment - committed. Trunk: r1405893 4x: r1405894
          Hide
          Commit Tag Bot added a comment -

          [branch_4x commit] James Dyer
          http://svn.apache.org/viewvc?view=revision&revision=1405920

          SOLR-4019: Fix tests that are invalid due to logging change

          Show
          Commit Tag Bot added a comment - [branch_4x commit] James Dyer http://svn.apache.org/viewvc?view=revision&revision=1405920 SOLR-4019 : Fix tests that are invalid due to logging change
          Hide
          Commit Tag Bot added a comment -

          [branch_4x commit] James Dyer
          http://svn.apache.org/viewvc?view=revision&revision=1405913

          SOLR-4019: Ignore tests that are invalid due to logging change

          Show
          Commit Tag Bot added a comment - [branch_4x commit] James Dyer http://svn.apache.org/viewvc?view=revision&revision=1405913 SOLR-4019 : Ignore tests that are invalid due to logging change
          Hide
          Commit Tag Bot added a comment -

          [branch_4x commit] James Dyer
          http://svn.apache.org/viewvc?view=revision&revision=1405894

          SOLR-4019: Log 503 stack traces unless from PingRequestHandler. Suppress logging some stack traces with ShowFileRequestHandler.

          Show
          Commit Tag Bot added a comment - [branch_4x commit] James Dyer http://svn.apache.org/viewvc?view=revision&revision=1405894 SOLR-4019 : Log 503 stack traces unless from PingRequestHandler. Suppress logging some stack traces with ShowFileRequestHandler.

            People

            • Assignee:
              James Dyer
              Reporter:
              Tomás Fernández Löbbe
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development