Solr
  1. Solr
  2. SOLR-3022

AbstractPluginLoader does not log caught exceptions

    Details

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

      Description

      I was setting up a new 4.x environment but forgot to put a custom Analyzer in the classpath. Unfortunately AbstractPluginLoader didn't log the exception and it took a long time for me to figure out why "No cores were created".

      1. SOLR-3022.patch
        1 kB
        Erick Erickson
      2. SOLR-3022.patch
        7 kB
        James Dyer
      3. SOLR-3022.patch
        5 kB
        James Dyer
      4. SOLR-3022.patch
        2 kB
        James Dyer

        Issue Links

          Activity

          James Dyer created issue -
          Hide
          James Dyer added a comment -

          AbstractPluginLoader (Trunk Only) is using the wrong constructor to create SolrExceptions, causing "alreadyLogged" to be set to true just prior to calling "logOnce". This patch fixes the problem.

          Show
          James Dyer added a comment - AbstractPluginLoader (Trunk Only) is using the wrong constructor to create SolrExceptions, causing "alreadyLogged" to be set to true just prior to calling "logOnce". This patch fixes the problem.
          James Dyer made changes -
          Field Original Value New Value
          Attachment SOLR-3022.patch [ 12510087 ]
          Hide
          Erick Erickson added a comment -

          Hmmm, this didn't fix the problem for me in trunk. I defined a bogus requestHandler like this:
          <requestHandler name="/eoe" class="eoe.solr.XmlUpdateRequestHandler"> </requestHandler>
          and got the same annoying "No cores were created" error message with no clue why.

          But if I put similar logic in RequestHandlers, around line 175 (the catch block in initHandlersFromConfig) I get useful traces. Or even just use SolrException.log rather than logOnce.

          But this behavior is different than 3x and I'm wondering if anyone has a clue why things were changed and whether the change was intentional. I looked over some back copies of these files, and they haven't changed in a looong time with the one caveat that the error is getting re-thrown in 4x but just falls out in 3x.

          So I'm looking for someone to weigh in on what the right thing to do is. I'm well aware that logging everything makes logging almost useless, but this behavior is suppressing useful information.

          BTW, I ran into this same problem with a plugin I was fooling around with a while ago, I'm glad you're pursuing it, thanks.

          Show
          Erick Erickson added a comment - Hmmm, this didn't fix the problem for me in trunk. I defined a bogus requestHandler like this: <requestHandler name="/eoe" class="eoe.solr.XmlUpdateRequestHandler"> </requestHandler> and got the same annoying "No cores were created" error message with no clue why. But if I put similar logic in RequestHandlers, around line 175 (the catch block in initHandlersFromConfig) I get useful traces. Or even just use SolrException.log rather than logOnce. But this behavior is different than 3x and I'm wondering if anyone has a clue why things were changed and whether the change was intentional. I looked over some back copies of these files, and they haven't changed in a looong time with the one caveat that the error is getting re-thrown in 4x but just falls out in 3x. So I'm looking for someone to weigh in on what the right thing to do is. I'm well aware that logging everything makes logging almost useless, but this behavior is suppressing useful information. BTW, I ran into this same problem with a plugin I was fooling around with a while ago, I'm glad you're pursuing it, thanks.
          Erick Erickson made changes -
          Assignee Erick Erickson [ erickerickson ]
          Hide
          Erick Erickson added a comment -

          Looking at this a bit more, there are a couple of issues:
          It looks like the change in behavior is a results of deprecating SolrConfig.severeErrors. Specifically, there is a bit of code in SolrDispatchFilter that prints out the severeErrors if:

          if( abortOnConfigurationError && SolrConfig.severeErrors.size() > 0 )

          { print stuff }

          Well, aborgOnConfigurationError is also deprecated with the comment:
          @deprecated all cores now abort on configuration error regardless of configuration

          But apparently they no longer print out the stack trace that is helpful. And the line in 3x solrconfig.xml that set abortOnConfigurationError=true has been removed so it defaults to false. But even when true, printStackTrace doesn't print out on trunk, I don't quite know why. I hacked some stuff and going into that loop and printing out getMessage() from every Throwable in that collection does print a message. But I'm not going to worry about that now...

          I wonder it this is related to this deprecation comment in SolrConfig.xml for severeErrors:
          "@deprecated All exceptions encountered during config parsing are now thrown by the respective constructors, preventing initialization."

          *********
          The other issue is that two SolrException c'tors hard code "logged=true", which puzzles me:

          public SolrException(ErrorCode code, Throwable th)

          { super(th); this.code=code.code; logged=true; <== what? }

          Would it make more sense to do something like:
          if (th instanceof SolrException)

          { logged = ((SolrExcption)th).logged; }

          else

          { logged = true; }

          And something similar for the other constructor that hard-codes true that has this signature:
          public SolrException(ErrorCode code, String msg, Throwable th)

          and let the default value of false stand otherwise? I could easily be persuaded that the else clause should be removed......

          Although this code hasn't changed since 3.x days, it still seems questionable to hard-code this to true.

          Anyway, the net-net of this is that we've lost some useful information. I'm not entirely comfortable with changing the constructors for SolrException to remove the hard-coded "true" without running it by folks. I would argue that doing what I outlined above makes sense, and if that results in more stack traces than we want people should use the c'tor that sets the logged value. What do you think?

          Show
          Erick Erickson added a comment - Looking at this a bit more, there are a couple of issues: It looks like the change in behavior is a results of deprecating SolrConfig.severeErrors. Specifically, there is a bit of code in SolrDispatchFilter that prints out the severeErrors if: if( abortOnConfigurationError && SolrConfig.severeErrors.size() > 0 ) { print stuff } Well, aborgOnConfigurationError is also deprecated with the comment: @deprecated all cores now abort on configuration error regardless of configuration But apparently they no longer print out the stack trace that is helpful. And the line in 3x solrconfig.xml that set abortOnConfigurationError=true has been removed so it defaults to false. But even when true, printStackTrace doesn't print out on trunk, I don't quite know why. I hacked some stuff and going into that loop and printing out getMessage() from every Throwable in that collection does print a message. But I'm not going to worry about that now... I wonder it this is related to this deprecation comment in SolrConfig.xml for severeErrors: "@deprecated All exceptions encountered during config parsing are now thrown by the respective constructors, preventing initialization." ********* The other issue is that two SolrException c'tors hard code "logged=true", which puzzles me: public SolrException(ErrorCode code, Throwable th) { super(th); this.code=code.code; logged=true; <== what? } Would it make more sense to do something like: if (th instanceof SolrException) { logged = ((SolrExcption)th).logged; } else { logged = true; } And something similar for the other constructor that hard-codes true that has this signature: public SolrException(ErrorCode code, String msg, Throwable th) and let the default value of false stand otherwise? I could easily be persuaded that the else clause should be removed...... Although this code hasn't changed since 3.x days, it still seems questionable to hard-code this to true. Anyway, the net-net of this is that we've lost some useful information. I'm not entirely comfortable with changing the constructors for SolrException to remove the hard-coded "true" without running it by folks. I would argue that doing what I outlined above makes sense, and if that results in more stack traces than we want people should use the c'tor that sets the logged value. What do you think?
          Hide
          James Dyer added a comment -

          I had noticed that problem constructor in SolrException also. I think it needs to be changed. Its used all over the place and in most cases, its a "new SolrException" being created and subsequently not being logged. But why should a developer have to dig through the constructors to check for gotchas like this?

          Here's a patch that adds a new constructor so developers can specify their intentions:

          public SolrException(ErrorCode code, Throwable th, boolean alreadyLogged) 
          

          And also changes the problem constructor to:

          public SolrException(ErrorCode code, Throwable th) {
          	super(th);
          	this.code=code.code;
          	if(th instanceof SolrException) {
          		this.logged=((SolrException) th).logged;
          	} else {
          		this.logged = false;
          	}
          }
          

          Reviewing all the places this is used, I left most of them alone but changed a few to suppress logging (with the new constructor) in cases where the problem is obviously being logged already. I also kept the suppressed logging for caught&wrapped "InterrupedException"s.

          Doing this will make the app a bit nosier but then again, each of these exceptions will log only once (right?). If we apply this, I wouldn't be surprised if there might be a case or two we will find it needs to be changed back to suppress the log message. But these should be easy to handle after-the-fact, right?

          Problem is, I'm not sure if this handles the issue you've discovered, when you have a bad RequestHandler in solrconfig.xml. I tried this with this new patch applied and I still didn't get a meaningful message logged. I'm now trying to get the latest trunk to deploy properly in my ide so I can debug...

          Show
          James Dyer added a comment - I had noticed that problem constructor in SolrException also. I think it needs to be changed. Its used all over the place and in most cases, its a "new SolrException" being created and subsequently not being logged. But why should a developer have to dig through the constructors to check for gotchas like this? Here's a patch that adds a new constructor so developers can specify their intentions: public SolrException(ErrorCode code, Throwable th, boolean alreadyLogged) And also changes the problem constructor to: public SolrException(ErrorCode code, Throwable th) { super (th); this .code=code.code; if (th instanceof SolrException) { this .logged=((SolrException) th).logged; } else { this .logged = false ; } } Reviewing all the places this is used, I left most of them alone but changed a few to suppress logging (with the new constructor) in cases where the problem is obviously being logged already. I also kept the suppressed logging for caught&wrapped "InterrupedException"s. Doing this will make the app a bit nosier but then again, each of these exceptions will log only once (right?). If we apply this, I wouldn't be surprised if there might be a case or two we will find it needs to be changed back to suppress the log message. But these should be easy to handle after-the-fact, right? Problem is, I'm not sure if this handles the issue you've discovered, when you have a bad RequestHandler in solrconfig.xml. I tried this with this new patch applied and I still didn't get a meaningful message logged. I'm now trying to get the latest trunk to deploy properly in my ide so I can debug...
          James Dyer made changes -
          Attachment SOLR-3022.patch [ 12510225 ]
          Mark Miller made changes -
          Link This issue relates to SOLR-2191 [ SOLR-2191 ]
          Hide
          Mark Miller added a comment -

          looks like this is related to SOLR-2191

          Show
          Mark Miller added a comment - looks like this is related to SOLR-2191
          Hide
          Erick Erickson added a comment - - edited

          Mark:

          You're right, this is totally related. I think it would be better to conditionally set the logged value based on the current value when passing in a throwable. How about if James and I handle the SolrException bit? Or are you about to check in 2191? and we can close this one?

          James:

          I had the same problem. There's another c'tor just above that one that looks like this:

            public SolrException(ErrorCode code, String msg, Throwable th) {
              this(code,msg,th,true);
            }
          
          

          That's the actual one being called in the RequestHandler case.

          I'm not a huge fan of zillion c'tors, perhaps all we really need is a comment for this c'tor

           public SolrException(ErrorCode code, String msg, Throwable th, boolean alreadyLogged) 
          

          that the msg can be null? In fact, it looks like both the msg and th parameters can all be null as far as the base java classes are concerned, so I wonder if we wouldn't be better off just making those c'tors all use the same one, like:

            public SolrException(ErrorCode code, String msg) {
              this(code, msg, null, false);
            }
          
            public SolrException(ErrorCode code, String msg, boolean alreadyLogged) {
              this(code, msg, null, alreadyLogged);
            }
          
            public SolrException(ErrorCode code, String msg, Throwable th, boolean alreadyLogged) {
              super(msg, th);
              this.code = code.code;
              logged = alreadyLogged;
            }
          
            public SolrException(ErrorCode code, String msg, Throwable th) {
              this(code, msg, th, (th instanceof SolrException) ? ((SolrException) th).logged : false);
            }
          
            public SolrException(ErrorCode code, Throwable th) {
              this(code, null, th, (th instanceof SolrException) ? ((SolrException) th).logged : false);
            }
          
          Show
          Erick Erickson added a comment - - edited Mark: You're right, this is totally related. I think it would be better to conditionally set the logged value based on the current value when passing in a throwable. How about if James and I handle the SolrException bit? Or are you about to check in 2191? and we can close this one? James: I had the same problem. There's another c'tor just above that one that looks like this: public SolrException(ErrorCode code, String msg, Throwable th) { this (code,msg,th, true ); } That's the actual one being called in the RequestHandler case. I'm not a huge fan of zillion c'tors, perhaps all we really need is a comment for this c'tor public SolrException(ErrorCode code, String msg, Throwable th, boolean alreadyLogged) that the msg can be null? In fact, it looks like both the msg and th parameters can all be null as far as the base java classes are concerned, so I wonder if we wouldn't be better off just making those c'tors all use the same one, like: public SolrException(ErrorCode code, String msg) { this (code, msg, null , false ); } public SolrException(ErrorCode code, String msg, boolean alreadyLogged) { this (code, msg, null , alreadyLogged); } public SolrException(ErrorCode code, String msg, Throwable th, boolean alreadyLogged) { super (msg, th); this .code = code.code; logged = alreadyLogged; } public SolrException(ErrorCode code, String msg, Throwable th) { this (code, msg, th, (th instanceof SolrException) ? ((SolrException) th).logged : false ); } public SolrException(ErrorCode code, Throwable th) { this (code, null , th, (th instanceof SolrException) ? ((SolrException) th).logged : false ); }
          Hide
          James Dyer added a comment -

          Here's a patch that changes both of the "problem constructors" by leaving "alreadyLogged" as false unless the passed-in Throwable happens to be a SolrException, in which case "alreadyLogged" is inherited.

          I also quickly reviewed each place this is used and manually switched to suppress logging in places it made sense. By the way, going through this revealed a lot of places where developers took pains to create nice loggable messages, but the SolrException constructor is making it so they'll never see the light of day.

          As for the duplication of SOLR-2191, it would be nice if we can maybe apply something simple like this patch first and see if it seems to meet everyone's need. Then if its not enough or if there still seems to be a reason to completely eliminate "logOnce", that could be done as a second step? This way we can fix the lost logging messages now and still have the option to do more (or less) later.

          I agree having lots of constructors is not usually a good idea. In an Exception class it might be nice though to retain them, giving developers added convenience. (and besides, its a lot of grunt work to get rid of the extra ones ).

          Show
          James Dyer added a comment - Here's a patch that changes both of the "problem constructors" by leaving "alreadyLogged" as false unless the passed-in Throwable happens to be a SolrException, in which case "alreadyLogged" is inherited. I also quickly reviewed each place this is used and manually switched to suppress logging in places it made sense. By the way, going through this revealed a lot of places where developers took pains to create nice loggable messages, but the SolrException constructor is making it so they'll never see the light of day. As for the duplication of SOLR-2191 , it would be nice if we can maybe apply something simple like this patch first and see if it seems to meet everyone's need. Then if its not enough or if there still seems to be a reason to completely eliminate "logOnce", that could be done as a second step? This way we can fix the lost logging messages now and still have the option to do more (or less) later. I agree having lots of constructors is not usually a good idea. In an Exception class it might be nice though to retain them, giving developers added convenience. (and besides, its a lot of grunt work to get rid of the extra ones ).
          James Dyer made changes -
          Attachment SOLR-3022.patch [ 12510248 ]
          Hide
          Erick Erickson added a comment -

          James:

          I wasn't advocating going through and replacing all the current constructors in the code, I was advocating just causing all the current constructors to funnel through the "one true constructor", more for aesthetics I suppose than function, although it does allow less room for fixing something up in one place and forgetting the other. And not introducing yet another constructor, I think we have enough already .

          Yeah, I think it'll be a bit of a phased approach. I'll see what I can do to get this patch and SOLR-2191 committed by next week, and maybe start up a patch for deprecating logOnce & etc.

          Show
          Erick Erickson added a comment - James: I wasn't advocating going through and replacing all the current constructors in the code, I was advocating just causing all the current constructors to funnel through the "one true constructor", more for aesthetics I suppose than function, although it does allow less room for fixing something up in one place and forgetting the other. And not introducing yet another constructor, I think we have enough already . Yeah, I think it'll be a bit of a phased approach. I'll see what I can do to get this patch and SOLR-2191 committed by next week, and maybe start up a patch for deprecating logOnce & etc.
          Erick Erickson made changes -
          Link This issue relates to SOLR-3032 [ SOLR-3032 ]
          Eric committed 1230573 (1 file)
          Reviews: none

          Fix for SOLR-3022 (Plugin Loader doesn't log exceptions). See SOLR-2191 and SOLR-3032 as well.

          Hide
          Erick Erickson added a comment -

          r: 1230573

          James:
          Thanks. As part of this whole shootin' match, I decided to just do the SolrException part of it, which fixes the original problem. All the rest of the work will go into 3022 which I'll start on shortly.

          Show
          Erick Erickson added a comment - r: 1230573 James: Thanks. As part of this whole shootin' match, I decided to just do the SolrException part of it, which fixes the original problem. All the rest of the work will go into 3022 which I'll start on shortly.
          Erick Erickson made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Hide
          Erick Erickson added a comment -

          Last comment. No CHANGES.txt entries for this as 3022 will encompass it and will also be the real set of changes.

          Show
          Erick Erickson added a comment - Last comment. No CHANGES.txt entries for this as 3022 will encompass it and will also be the real set of changes.
          Hide
          Erick Erickson added a comment -

          Final version of patch.

          Show
          Erick Erickson added a comment - Final version of patch.
          Erick Erickson made changes -
          Attachment SOLR-3022.patch [ 12510375 ]
          Eric committed 1230599 (1 file)
          Reviews: none

          Part of SOLR-3022. It seems like a good idea to retrofit NOT defaulting to true for "alreadyLogged"

          Hide
          Erick Erickson added a comment -

          Committed to 3x, r: 1230599

          Show
          Erick Erickson added a comment - Committed to 3x, r: 1230599
          Erick Erickson made changes -
          Affects Version/s 3.6 [ 12319065 ]
          Michael Ryan made changes -
          Link This issue breaks SOLR-3496 [ SOLR-3496 ]
          Uwe Schindler made changes -
          Status Resolved [ 5 ] Closed [ 6 ]

            People

            • Assignee:
              Erick Erickson
              Reporter:
              James Dyer
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development