Solr
  1. Solr
  2. SOLR-2191

Change SolrException cstrs that take Throwable to default to alreadyLogged=false

    Details

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

      Description

      Because of misuse, many exceptions are now not logged at all - can be painful when doing dev. I think we should flip this setting and work at removing any double logging - losing logging is worse (and it almost looks like we lose more logging than we would get in double logging) - and bad solrexception/logging patterns are proliferating.

      1. SOLR-2191.patch
        15 kB
        Mark Miller

        Issue Links

          Activity

          Hide
          Mark Miller added a comment -

          patch that enables the logging of a whole slew of exceptions

          Show
          Mark Miller added a comment - patch that enables the logging of a whole slew of exceptions
          Hide
          Hoss Man added a comment -

          See also the comments in SOLR-2124 where the funkiness of logOnce is causing a real problem with the Ping handler.

          Show
          Hoss Man added a comment - See also the comments in SOLR-2124 where the funkiness of logOnce is causing a real problem with the Ping handler.
          Hide
          David Smiley added a comment -

          Yes, lets do this! I was just about to log a bug when I found it's already been reported. I had some stupid error in my solr config and it never got logged. Because of the error, the core never got registered into the container. And then when I went to do any queries, Solr kept telling me I didn't specify a core name when I never had to before (using the default). I was in the twilight zone for a while.

          Mark, you're a committer yet you supplied a patch. Why didn't you simply commit it? I heard on the dev list recently that Solr is supposedly CTR (commit then review), yet we clearly act here as RTC. So even if RTC is it, wouldn't there be some threshold to let simple things like this through without a review?

          Show
          David Smiley added a comment - Yes, lets do this! I was just about to log a bug when I found it's already been reported. I had some stupid error in my solr config and it never got logged. Because of the error, the core never got registered into the container. And then when I went to do any queries, Solr kept telling me I didn't specify a core name when I never had to before (using the default). I was in the twilight zone for a while. Mark, you're a committer yet you supplied a patch. Why didn't you simply commit it? I heard on the dev list recently that Solr is supposedly CTR (commit then review), yet we clearly act here as RTC. So even if RTC is it, wouldn't there be some threshold to let simple things like this through without a review?
          Hide
          Mark Miller added a comment -

          Why didn't you simply commit it? I heard on the dev list recently that Solr is supposedly CTR (commit then review), yet we clearly act here as RTC.

          Depends really - on the change and on the committer. We like to keep trunk extra shiny, and I think our practice is good myself. But it's up to each committer.

          So even if RTC is it, wouldn't there be some threshold to let simple things like this through without a review?

          Yes - and many small things are simply committed. Likely when I ran into this, I was doing other things - and I made a quick patch, but not something I was willing to stake my name on as a commit. I like to do a thorough review first. And then this just fell off my radar. Sometimes you are just not sure of all of the ramifications of your change - a lot of times this is a mini side track while I'm doing something else, and so it's nice to just toss up a patch and get feedback from the likes of Hossman and others before just cowboying on trunk. Again though - each situation is handled by each committer based on their level of comfort, and the general culture of the community.

          Yeah, this bug is annoying - I'm happy to look at this again soon - I happen to be unusually busy at this time, but I'll certainly try to get this in by this weekend.

          Show
          Mark Miller added a comment - Why didn't you simply commit it? I heard on the dev list recently that Solr is supposedly CTR (commit then review), yet we clearly act here as RTC. Depends really - on the change and on the committer. We like to keep trunk extra shiny, and I think our practice is good myself. But it's up to each committer. So even if RTC is it, wouldn't there be some threshold to let simple things like this through without a review? Yes - and many small things are simply committed. Likely when I ran into this, I was doing other things - and I made a quick patch, but not something I was willing to stake my name on as a commit. I like to do a thorough review first. And then this just fell off my radar. Sometimes you are just not sure of all of the ramifications of your change - a lot of times this is a mini side track while I'm doing something else, and so it's nice to just toss up a patch and get feedback from the likes of Hossman and others before just cowboying on trunk. Again though - each situation is handled by each committer based on their level of comfort, and the general culture of the community. Yeah, this bug is annoying - I'm happy to look at this again soon - I happen to be unusually busy at this time, but I'll certainly try to get this in by this weekend.
          Hide
          Mark Miller added a comment -

          Also keep in mind that Review-Then-Commit at Apache means you need consensus and 3 votes before committing I believe:

          See

          http://www.apache.org/foundation/glossary.html

          Consensus Approval
          'Consensus approval' refers to a vote (sense 1) which has completed with at least three binding +1 votes and no vetos. Compare .

          Review-Then-Commit
          (Often referenced as 'RTC' or 'R-T-C'.) Commit policy which requires that all changes receive consensus approval in order to be committed. Compare , and see the description of the voting process.

          Show
          Mark Miller added a comment - Also keep in mind that Review-Then-Commit at Apache means you need consensus and 3 votes before committing I believe: See http://www.apache.org/foundation/glossary.html Consensus Approval 'Consensus approval' refers to a vote (sense 1) which has completed with at least three binding +1 votes and no vetos. Compare . Review-Then-Commit (Often referenced as 'RTC' or 'R-T-C'.) Commit policy which requires that all changes receive consensus approval in order to be committed. Compare , and see the description of the voting process.
          Hide
          Mark Miller added a comment -

          Also keep in mind that Review-Then-Commit at Apache means you need consensus and 3 votes before committing I believe:

          See

          http://www.apache.org/foundation/glossary.html

          Consensus Approval
          'Consensus approval' refers to a vote (sense 1) which has completed with at least three binding +1 votes and no vetos. Compare .

          Review-Then-Commit
          (Often referenced as 'RTC' or 'R-T-C'.) Commit policy which requires that all changes receive consensus approval in order to be committed. Compare , and see the description of the voting process.

          Show
          Mark Miller added a comment - Also keep in mind that Review-Then-Commit at Apache means you need consensus and 3 votes before committing I believe: See http://www.apache.org/foundation/glossary.html Consensus Approval 'Consensus approval' refers to a vote (sense 1) which has completed with at least three binding +1 votes and no vetos. Compare . Review-Then-Commit (Often referenced as 'RTC' or 'R-T-C'.) Commit policy which requires that all changes receive consensus approval in order to be committed. Compare , and see the description of the voting process.
          Hide
          David Smiley added a comment -

          Thanks for clarification on Review Then Commit (RTC); I verified through ASF's documentation that indeed three votes is necessary. Wow, it'd take forever to get things done that way; it seems impractical for anything but perhaps security related code (e.g. crypto). I didn't see any info exceptions for "minor" changes (e.g. adding documentation, code formatting). I'm glad we don't do that officially.

          I'm about to take the conversation further on the dev list RE jira issues falling through the cracks...

          Show
          David Smiley added a comment - Thanks for clarification on Review Then Commit (RTC); I verified through ASF's documentation that indeed three votes is necessary. Wow, it'd take forever to get things done that way; it seems impractical for anything but perhaps security related code (e.g. crypto). I didn't see any info exceptions for "minor" changes (e.g. adding documentation, code formatting). I'm glad we don't do that officially. I'm about to take the conversation further on the dev list RE jira issues falling through the cracks...
          Hide
          Hoss Man added a comment -

          Is anyone else interested in entertaining the notion that the "alreadyLogged" concept is more trouble then it's worth and we should just rip the whole damn thing out? (deprecate logOnce, etc...)

          is there such a thing as logging an exception "too much"? and if there is, couldn't we fix those code paths to be less chatty?

          Show
          Hoss Man added a comment - Is anyone else interested in entertaining the notion that the "alreadyLogged" concept is more trouble then it's worth and we should just rip the whole damn thing out? (deprecate logOnce, etc...) is there such a thing as logging an exception "too much"? and if there is, couldn't we fix those code paths to be less chatty?
          Hide
          David Smiley added a comment -

          Ehh... I kind of like the notion but wether it is kept or not, I think a general error/exception strategy needs to be devised.

          In code I write, I tend to almost never log exceptions; I let them get to the highest possible point to ensure they are logged there once, which is usually one place. Beforehand I might catch an exception to do a log.error() to provide some context and then rethrow the exception. I also wrap with RuntimeExceptions.

          An alternative is to log exceptions early (with contextual error message), and then rethrow but don't log it higher up (e.g. earlier up) the stack. But how can that early point know the exception has been handled? It can't generically know making your suggestion of "fix those code paths to be less chatty" problematic. Perhaps our code will always assume that we logged an exception before wrapping it in SolrException right before we throw them. I think that's a reasonable policy and wouldn't require an alreadyLogged flag.

          Show
          David Smiley added a comment - Ehh... I kind of like the notion but wether it is kept or not, I think a general error/exception strategy needs to be devised. In code I write, I tend to almost never log exceptions; I let them get to the highest possible point to ensure they are logged there once, which is usually one place. Beforehand I might catch an exception to do a log.error() to provide some context and then rethrow the exception. I also wrap with RuntimeExceptions. An alternative is to log exceptions early (with contextual error message), and then rethrow but don't log it higher up (e.g. earlier up) the stack. But how can that early point know the exception has been handled? It can't generically know making your suggestion of "fix those code paths to be less chatty" problematic. Perhaps our code will always assume that we logged an exception before wrapping it in SolrException right before we throw them. I think that's a reasonable policy and wouldn't require an alreadyLogged flag.
          Hide
          Yonik Seeley added a comment -

          In code I write, I tend to almost never log exceptions; I let them get to the highest possible point to ensure they are logged there once, which is usually one place. Beforehand I might catch an exception to do a log.error() to provide some context and then rethrow the exception.

          Right. And logging immediately can be problematic since one may not know if it's really an error that should be logged since Exceptions can sometimes be handled (dismax is one example).

          Anyway, certainly a +1 from me for changing the default of alreadyLogged and improving the strategy in general.

          Show
          Yonik Seeley added a comment - In code I write, I tend to almost never log exceptions; I let them get to the highest possible point to ensure they are logged there once, which is usually one place. Beforehand I might catch an exception to do a log.error() to provide some context and then rethrow the exception. Right. And logging immediately can be problematic since one may not know if it's really an error that should be logged since Exceptions can sometimes be handled (dismax is one example). Anyway, certainly a +1 from me for changing the default of alreadyLogged and improving the strategy in general.
          Hide
          Mark Miller added a comment -

          I have not forgot about this - just has gotten bigger with recent comments - perhaps we commit this first, then address the larger issue?

          Show
          Mark Miller added a comment - I have not forgot about this - just has gotten bigger with recent comments - perhaps we commit this first, then address the larger issue?
          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
          Sami Siren added a comment -

          I also ran into this problem too (SOLR-3006).

          b1. I have not forgot about this - just has gotten bigger with recent comments - perhaps we commit this first, then address the larger issue?

          Sounds like a good start to me. The current situation where log messages can easily get lost is really annoying.

          Show
          Sami Siren added a comment - I also ran into this problem too ( SOLR-3006 ). b1. I have not forgot about this - just has gotten bigger with recent comments - perhaps we commit this first, then address the larger issue? Sounds like a good start to me. The current situation where log messages can easily get lost is really annoying.
          Hide
          David Smiley added a comment -

          Yes please commit this for pete's sake! This is one of those JIRA issues that has fallen through the cracks and nearly forgotten.

          Show
          David Smiley added a comment - Yes please commit this for pete's sake! This is one of those JIRA issues that has fallen through the cracks and nearly forgotten.
          Hide
          Mark Miller added a comment -

          The issue needs to be updated. I think the right approach is to remove logOnce.

          Show
          Mark Miller added a comment - The issue needs to be updated. I think the right approach is to remove logOnce.
          Hide
          Erick Erickson added a comment -

          What does "remove logOnce" mean in this case? Remove the method, sure. But note that the log(...) methods at least set the 'logged' value. Should that variable be removed too in your opinion?

          I think I favor just removing logOnce, and expanding the use of 'logged' in the log(...) methods to return if it's already set at the top. I really dislike the idea of trying to keep track of where an exception is really reported, there are just too many code paths.....

          If people want to let the upper layers handle reporting, they can wrap the exception in a SolrException and re-throw, optionally logging the error at that point. If they don't wrap the exception and do log it, it may be re-logged later but that's a personal problem that should be dealt with on a case-by-case basis.

          Should anything be done with 3.6, i.e. deprecate whatever we decide so we can nuke it in 5.x?

          I may well commit this and open up another JIRA for further work. SOLR-3022 deals with this too. I'd like to consolidate all this by this weekend, any others out there?

          Show
          Erick Erickson added a comment - What does "remove logOnce" mean in this case? Remove the method, sure. But note that the log(...) methods at least set the 'logged' value. Should that variable be removed too in your opinion? I think I favor just removing logOnce, and expanding the use of 'logged' in the log(...) methods to return if it's already set at the top. I really dislike the idea of trying to keep track of where an exception is really reported, there are just too many code paths..... If people want to let the upper layers handle reporting, they can wrap the exception in a SolrException and re-throw, optionally logging the error at that point. If they don't wrap the exception and do log it, it may be re-logged later but that's a personal problem that should be dealt with on a case-by-case basis. Should anything be done with 3.6, i.e. deprecate whatever we decide so we can nuke it in 5.x? I may well commit this and open up another JIRA for further work. SOLR-3022 deals with this too. I'd like to consolidate all this by this weekend, any others out there?
          Hide
          Mark Miller added a comment -

          personal problem that should be dealt with on a case-by-case basis.

          I think it's more of a project level problem - we have to decide how we want to handle logging and stick with it I think. It still seems the most sensible thing is to drop this logOnce concept entirely - logging should be handled at the fringes once the exception bubbles up.

          Should that variable be removed too in your opinion?

          Yup - I think logged and logOnce should die die die.

          Show
          Mark Miller added a comment - personal problem that should be dealt with on a case-by-case basis. I think it's more of a project level problem - we have to decide how we want to handle logging and stick with it I think. It still seems the most sensible thing is to drop this logOnce concept entirely - logging should be handled at the fringes once the exception bubbles up. Should that variable be removed too in your opinion? Yup - I think logged and logOnce should die die die.
          Hide
          Yonik Seeley added a comment -

          I think it's more of a project level problem - we have to decide how we want to handle logging and stick with it I think.

          There's not much of a choice is there? Logging early isn't always possible since there is a lack of context (for logging and for deciding if it should be logged). Logging last means your missing context for extra debugging info. I guess that leaves us living with logging the same exception multiple times (since we don't know if it's already been logged).

          Show
          Yonik Seeley added a comment - I think it's more of a project level problem - we have to decide how we want to handle logging and stick with it I think. There's not much of a choice is there? Logging early isn't always possible since there is a lack of context (for logging and for deciding if it should be logged). Logging last means your missing context for extra debugging info. I guess that leaves us living with logging the same exception multiple times (since we don't know if it's already been logged).
          Hide
          Mark Miller added a comment -

          Logging last means your missing context for extra debugging info.

          Why? You just include the extra context in the exception that you throw.

          I guess that leaves us living with logging the same exception multiple times

          I don't see why - I still think they should bubble up and get logged at the top.

          Show
          Mark Miller added a comment - Logging last means your missing context for extra debugging info. Why? You just include the extra context in the exception that you throw. I guess that leaves us living with logging the same exception multiple times I don't see why - I still think they should bubble up and get logged at the top.
          Hide
          David Smiley added a comment -

          I agree with Mark. In code I write, I am always sure to tag on the old exception to a new one, assuming I need to throw a different exception, and I almost never log exceptions. I let the top layers handle that. Code that does otherwise has redundant logs which I find annoying.

          Show
          David Smiley added a comment - I agree with Mark. In code I write, I am always sure to tag on the old exception to a new one, assuming I need to throw a different exception, and I almost never log exceptions. I let the top layers handle that. Code that does otherwise has redundant logs which I find annoying.
          Hide
          Yonik Seeley added a comment -

          Why? You just include the extra context in the exception that you throw.

          I vaguely recall having issues (way in the past) with big multi-line exception messages.
          Guess I'll have to wait and see how it works in practice.

          Show
          Yonik Seeley added a comment - Why? You just include the extra context in the exception that you throw. I vaguely recall having issues (way in the past) with big multi-line exception messages. Guess I'll have to wait and see how it works in practice.
          Hide
          Erick Erickson added a comment -

          OK, this really breaks out into two parts. I've fixed the SolrException part in both 3.6 and trunk. I'll leave this part to Mark (he agrees) as far as dealing with ZooKeeper messages.

          Show
          Erick Erickson added a comment - OK, this really breaks out into two parts. I've fixed the SolrException part in both 3.6 and trunk. I'll leave this part to Mark (he agrees) as far as dealing with ZooKeeper messages.
          Hide
          Erick Erickson added a comment -

          back to you for the ZK stuff. SolrException changes are committed.

          Show
          Erick Erickson added a comment - back to you for the ZK stuff. SolrException changes are committed.
          Hide
          Erick Erickson added a comment -

          One last comment. Let's move further discussion of this over to SOLR-3032 where I'll be putting up a first-cut today or tomorrow (hopefully).

          Show
          Erick Erickson added a comment - One last comment. Let's move further discussion of this over to SOLR-3032 where I'll be putting up a first-cut today or tomorrow (hopefully).
          Hide
          James Dyer added a comment -

          With SOLR-3022 and SOLR-3032 complete, should this one be closed also?

          Show
          James Dyer added a comment - With SOLR-3022 and SOLR-3032 complete, should this one be closed also?
          Hide
          Mark Miller added a comment -

          Sure, makes sense to me.

          Show
          Mark Miller added a comment - Sure, makes sense to me.

            People

            • Assignee:
              Mark Miller
              Reporter:
              Mark Miller
            • Votes:
              1 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development