Velocity
  1. Velocity
  2. VELOCITY-467

Throw more exceptions and log less errors

    Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 1.5 beta1
    • Fix Version/s: 1.6
    • Component/s: Engine
    • Labels:
      None

      Description

      Now that Velocity application exceptions are based on RuntimeException, we have more opportunity to use exceptions to signal application level problems. I'm particularly concerned about initialization problems that are logged and may be missed. We need to review all logged error messages and see if it would be more appropriate to throw an exception instead. Some of these places we may need to leave as is for backwards compatibility reasons. (e.g. macro in the global macro library doesn't parse properly).

      Llewellyn Falco made a good case for this on the dev list recently:

      http://www.mail-archive.com/velocity-dev@jakarta.apache.org/msg15067.html

      #####
      I still would like to put in my vote that sending error's to the log is an incredibly BAD idea.

      If something is not working, it should be LOUDLY shown as an exception.
      If it is working I don't really need a log.

      The (velocity) log should be there for velocity developers (those programming the actual velocity code) not users.

      I don't ever care to see tomcat's log, I care to see the things I log while in tomcat.

      Most of all, many many many people do not check the log at all, let alone frequently.
      ####

        Activity

        Hide
        Adrian Tarau added a comment -

        Thanks Nathan, looking good

        Show
        Adrian Tarau added a comment - Thanks Nathan, looking good
        Hide
        Nathan Bubna added a comment -

        OK, i think this is essentially resolved.

        Show
        Nathan Bubna added a comment - OK, i think this is essentially resolved.
        Hide
        Adrian Tarau added a comment -

        I would say it is wrong, but how much? I think it depends on application type.
        Which scenario is better? :
        1. Just log the error(so the developers will know) and some small part of the web page(we are still building an web application) will be missing but the user could still use the page(assuming the missing part is not critical)
        2. Throw an exception, the user will get an "Sorry we have a problem, came back later".

        I think(in general in software development) it is preferable to fail (fast) instead of giving partial results, but this could not work for everybody. Fail or error it is for sure better (my opinion) than debug for handling wrong type passed to #foreach.

        Yes, something like that would be great. Thanks.

        Show
        Adrian Tarau added a comment - I would say it is wrong, but how much? I think it depends on application type. Which scenario is better? : 1. Just log the error(so the developers will know) and some small part of the web page(we are still building an web application) will be missing but the user could still use the page(assuming the missing part is not critical) 2. Throw an exception, the user will get an "Sorry we have a problem, came back later". I think(in general in software development) it is preferable to fail (fast) instead of giving partial results, but this could not work for everybody. Fail or error it is for sure better (my opinion) than debug for handling wrong type passed to #foreach. Yes, something like that would be great. Thanks.
        Hide
        Nathan Bubna added a comment -

        If passing the wrong type to a #foreach is "really wrong," then an exception should probably be thrown. Of course, for backwards compatibility, we can't make that the default behavior. So, perhaps this is a place for another "strictMode" patch like what i just did for the AST math nodes.

        Show
        Nathan Bubna added a comment - If passing the wrong type to a #foreach is "really wrong," then an exception should probably be thrown. Of course, for backwards compatibility, we can't make that the default behavior. So, perhaps this is a place for another "strictMode" patch like what i just did for the AST math nodes.
        Hide
        Adrian Tarau added a comment -

        Because your logging level in production is WARN or INFO. Except if you are investigating something(like getting an exception and you want to see more details) you will not have DEBUG level set in production. In this case if something went wrong you will not know(we assume you are looking at the logs for errors or have some sort of notification when something is logged with error level).

        I'm fine using DEBUG in general, since you are interested only at development time to see what went wrong, but in production you will not have DEBUG so at some extent things that are really wrong(passing wrong type to #foreach) should be logged as errors. In this case a custom Uberspect will the "problem", but still...

        Just my 2 cents

        Show
        Adrian Tarau added a comment - Because your logging level in production is WARN or INFO. Except if you are investigating something(like getting an exception and you want to see more details) you will not have DEBUG level set in production. In this case if something went wrong you will not know(we assume you are looking at the logs for errors or have some sort of notification when something is logged with error level). I'm fine using DEBUG in general, since you are interested only at development time to see what went wrong, but in production you will not have DEBUG so at some extent things that are really wrong(passing wrong type to #foreach) should be logged as errors. In this case a custom Uberspect will the "problem", but still... Just my 2 cents
        Hide
        Nathan Bubna added a comment -

        Why does a debug level message not count as informing you when a wrong object is passed to a #foreach?

        If you would like, we now have chainable and linkable uberspect support in 1.6. Custom uberspect'ing is easier than ever. Feel free to implement an Uberspect that watches for such things and does whatever you want for getIterator().

        Show
        Nathan Bubna added a comment - Why does a debug level message not count as informing you when a wrong object is passed to a #foreach? If you would like, we now have chainable and linkable uberspect support in 1.6. Custom uberspect'ing is easier than ever. Feel free to implement an Uberspect that watches for such things and does whatever you want for getIterator().
        Hide
        Adrian Tarau added a comment -

        One more thing : I agree, warn should not be used with Velocity. Levels like debug, info and error should be used and exceptions during initialization.

        Show
        Adrian Tarau added a comment - One more thing : I agree, warn should not be used with Velocity. Levels like debug, info and error should be used and exceptions during initialization.
        Hide
        Adrian Tarau added a comment -

        However, I'm still convinced that in this case(and maybe some other cases) I would like to be informed when a wrong object is passed to a #foreach. I agree, this should be done on the application side, your code should be protected for this kind of "failures" - passing wrong types.
        Of course, some logging/listeners which can provide support for the application to distinguish and take action for this kind of "problems" would be preferable. I would really love to see that happening in 1.7.

        Show
        Adrian Tarau added a comment - However, I'm still convinced that in this case(and maybe some other cases) I would like to be informed when a wrong object is passed to a #foreach. I agree, this should be done on the application side, your code should be protected for this kind of "failures" - passing wrong types. Of course, some logging/listeners which can provide support for the application to distinguish and take action for this kind of "problems" would be preferable. I would really love to see that happening in 1.7.
        Hide
        Adrian Tarau added a comment -

        Logging distinguished by category would be a nice thing to have

        Show
        Adrian Tarau added a comment - Logging distinguished by category would be a nice thing to have
        Hide
        Will Glass-Husain added a comment -

        That makes sense to me. My logs are littered with Velocity error messages that are not significant from the perspective of the larger app.

        We're providing a number of new features to help app developers catch reference failures. Most other stuff doesn't matter.

        Show
        Will Glass-Husain added a comment - That makes sense to me. My logs are littered with Velocity error messages that are not significant from the perspective of the larger app. We're providing a number of new features to help app developers catch reference failures. Most other stuff doesn't matter.
        Hide
        Nathan Bubna added a comment -

        No, i don't think raising the log level for those things is going to be all that helpful. When those occur due to a mistake, the output should be wrong. This is error and warning enough, if they can't tell from that what happened, they can set logging to debug level for more info. This is the general stance and trend we've decided for Velocity, and i'm loathe to begin making exceptions in the other direction.

        My current log-level guide for Velocity is roughly:

        trace - pointless because really, AOP or a debugger is better for this
        debug - for anyone looking to find out why their output wasn't as expected
        info - useless, don't bother
        warn - barely tolerated where some prior setting is preventing a requested action (really debug ought to be sufficient)
        error - hope to soon be just for logging about the exception about to be thrown

        you might say that i've come to see log levels as largely pointless, especially for Velocity. there's only two jobs for logs, tracking down reasons for wrong behavior (debug) and recording total failures (error). really, when it comes to logging for component libraries like Velocity, the user (either a framework, app or different library) is probably a better judge of the "level" of gravity any log statement should have than the library developer. If in some future time i rewrite Velocity's logging, you're more likely to see logging distinguished by category (introspection, macros, parsing, resource management) and mode (debug, production) than by any sort of level. For now, i'm content to just mimic the two modes by moving all logging to debug or error levels.

        Show
        Nathan Bubna added a comment - No, i don't think raising the log level for those things is going to be all that helpful. When those occur due to a mistake, the output should be wrong. This is error and warning enough, if they can't tell from that what happened, they can set logging to debug level for more info. This is the general stance and trend we've decided for Velocity, and i'm loathe to begin making exceptions in the other direction. My current log-level guide for Velocity is roughly: trace - pointless because really, AOP or a debugger is better for this debug - for anyone looking to find out why their output wasn't as expected info - useless, don't bother warn - barely tolerated where some prior setting is preventing a requested action (really debug ought to be sufficient) error - hope to soon be just for logging about the exception about to be thrown you might say that i've come to see log levels as largely pointless, especially for Velocity. there's only two jobs for logs, tracking down reasons for wrong behavior (debug) and recording total failures (error). really, when it comes to logging for component libraries like Velocity, the user (either a framework, app or different library) is probably a better judge of the "level" of gravity any log statement should have than the library developer. If in some future time i rewrite Velocity's logging, you're more likely to see logging distinguished by category (introspection, macros, parsing, resource management) and mode (debug, production) than by any sort of level. For now, i'm content to just mimic the two modes by moving all logging to debug or error levels.
        Hide
        Adrian Tarau added a comment -

        Looking at 102 I've notices a change in logging(from error -> debug) and I have a few comments on public Iterator getIterator(Object obj, Info i)

        Since it is a part of a public API obj should be checked for NULL and this method should return an empty iterator implementation and not NULL(static instance, always the same).#foreach does saves some CPU when iterator is null, but most of the time we expect a non-null interator.

        Checking for a possible Iterable with Method iter = type.getMethod("iterator", null); should log at least a warning in case of a wrong return type, or an error as it was before. A nicer way it will be to scan for Iterable and use the method cache. Somebody could have an "iterator" method but designed to do something else.

        Also at the end, it should log the message "Could not determine type of iterator in #foreach loop at" as a warning at least, I would say error or exception We really want to point that the loop will not be executed probably because a wrong type. There is only one case when the loop should be skipped without a warning and this is when obj == NULL.

        Show
        Adrian Tarau added a comment - Looking at 102 I've notices a change in logging(from error -> debug) and I have a few comments on public Iterator getIterator(Object obj, Info i) Since it is a part of a public API obj should be checked for NULL and this method should return an empty iterator implementation and not NULL(static instance, always the same).#foreach does saves some CPU when iterator is null, but most of the time we expect a non-null interator. Checking for a possible Iterable with Method iter = type.getMethod("iterator", null); should log at least a warning in case of a wrong return type, or an error as it was before. A nicer way it will be to scan for Iterable and use the method cache. Somebody could have an "iterator" method but designed to do something else. Also at the end, it should log the message "Could not determine type of iterator in #foreach loop at" as a warning at least, I would say error or exception We really want to point that the loop will not be executed probably because a wrong type. There is only one case when the loop should be skipped without a warning and this is when obj == NULL.
        Hide
        Nathan Bubna added a comment -

        Most of the remaining places where an error is logged without an exception thrown are in the various AST[MathOp]Node classes when one of the variables is null.

        I'm not sure we really want to start throwing exceptions in these cases, at least not by default. These are not fatal errors; so throwing an exception would be a break in backwards compatibility.

        I think perhaps we ought to make this configurable, defaulting to log-only. Also, we might want a new VelocityMathException or something like that, to distinguish these.

        Show
        Nathan Bubna added a comment - Most of the remaining places where an error is logged without an exception thrown are in the various AST [MathOp] Node classes when one of the variables is null. I'm not sure we really want to start throwing exceptions in these cases, at least not by default. These are not fatal errors; so throwing an exception would be a break in backwards compatibility. I think perhaps we ought to make this configurable, defaulting to log-only. Also, we might want a new VelocityMathException or something like that, to distinguish these.
        Hide
        Will Glass-Husain added a comment -

        just a reminder to do a pass through the code reviewing log levels

        Show
        Will Glass-Husain added a comment - just a reminder to do a pass through the code reviewing log levels

          People

          • Assignee:
            Unassigned
            Reporter:
            Will Glass-Husain
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development