Velocity Tools
  1. Velocity Tools
  2. VELTOOLS-59

WebappLoader's isSourceModified() and getLastModified() sometimes fail

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 1.1, 1.2, 1.3, 2.x
    • Fix Version/s: 1.3, 2.x
    • Component/s: VelocityView
    • Labels:
      None
    • Environment:
      WebSphere v5.1.x on Linux and Win32, possibly other appservers or versions of WebSphere as well.

      Description

      The org.apache.velocity.tools.view.servlet.WebappLoader class ensures that all the paths it can load from end with the '/' character. When loading a template from disk in getResourceStream(), WebappLoader ensures that the file to be loaded does not start with a '/' character, so the file always loads properly.

      However, in isSourceModified(Resource resource) and getLastModified(Resource resource), the same sanity check is not made on the path of the resource, so you can have a path like /myApp//some/file.vm. The result of this, in my environment(s) at least, is that the isSourceModified() check always returns true because the file cannot be found. With caching turned on, this leaves you with with the Least Efficient Cache Ever, since it always re-reads any template requested after the modificationCheckInterval.

      I haven't looked at it carefully, but I think FileResourceLoader may have the same behavior.

      An interesting side effect of this unruly behavior is, I think, a race-condition bug in the Template class. In the process() method, the first thing it does is set its "data" member, the AST of the template, to null. However, another thread can get that same data member while it's uninitialized. This leads to the "java.lang.Exception: Template.merge() failure. The document is null, most likely due to parsing error." error. A google search for "Template.merge() failure" turns up a couple web applications that, I think, are falling prey to this problem as well. This problem is easy to duplicate:
      1. Enable resource loader caching
      2. Set the modificationCheckInterval to something small, like 10 seconds.
      3. Hammer your application with requests.

      I'm not intimately familiar with the internals of velocity, so I'm not sure what the fix should be, or even where it should go. FWIW, I ended up writing my own ResourceLoader that expects a leading '/' on all template names. Thoughts?

        Activity

        Stu Belden created issue -
        Hide
        Nathan Bubna added a comment -

        Nice catch. Thanks for reporting this! It seems to me the solution is to just do the same sanity check during isSourceModified() and getLastModified(). Should be easy. I'll put this on my TODO stack.

        I'm not sure, however, that i understand how the caching problem is causing the merge failure, but i'll take your word for it. the fact that a cache failure is causing this seems wrong to me; i wonder if there's something else that needs fixing in the template merge process. Will? Geir? any ideas?

        Show
        Nathan Bubna added a comment - Nice catch. Thanks for reporting this! It seems to me the solution is to just do the same sanity check during isSourceModified() and getLastModified(). Should be easy. I'll put this on my TODO stack. I'm not sure, however, that i understand how the caching problem is causing the merge failure, but i'll take your word for it. the fact that a cache failure is causing this seems wrong to me; i wonder if there's something else that needs fixing in the template merge process. Will? Geir? any ideas?
        Hide
        Nathan Bubna added a comment -

        I'll take a look at FileResourceLoader to confirm/fix it there too.

        Show
        Nathan Bubna added a comment - I'll take a look at FileResourceLoader to confirm/fix it there too.
        Nathan Bubna made changes -
        Field Original Value New Value
        Affects Version/s 1.3 [ 12310349 ]
        Assignee Nathan Bubna [ nbubna ]
        Affects Version/s 2.0 [ 12310350 ]
        Affects Version/s 1.1 [ 12310347 ]
        Fix Version/s 2.0 [ 12310350 ]
        Fix Version/s 1.3 [ 12310349 ]
        Hide
        Will Glass-Husain added a comment -

        Nice catch!

        Nathan - your suggestion makes sense.

        I'm a little worried about the race condition issue. Maybe we should put some kind of block in there until template initialization is complete?

        Show
        Will Glass-Husain added a comment - Nice catch! Nathan - your suggestion makes sense. I'm a little worried about the race condition issue. Maybe we should put some kind of block in there until template initialization is complete?
        Hide
        Marc Novakowski added a comment -

        While load testing our application, I think I ran into the race condition mentioned above. The entries in the log file looked something like this:

        ERROR Exception rendering #parse( /include/leaderboard.vm ) : java.lang.NullPointerException
        ERROR Exception rendering #parse( /detail/album_layout.vm ) : java.lang.NullPointerException

        and sometimes:

        ERROR Template.merge() failure. The document is null, most likely due to parsing error.
        ERROR VelocityViewServlet: Exception processing the template: java.lang.Exception: Template.merge() failure. The document is null, most likely due to parsing error.

        We fixed it by turning off the "modificationCheckInterval" (which had been set to 4, it is now set to 0). This workaround is adequate for us, since we don't modify template files on-the-fly in production. But it would be nice to know that the underlying bug is fixed at some point!

        In order to replicate this race condition, I had to put a lot of simulated load on the server. I used a tool called "siege" with the following arguments:

        siege -t 1H -i -b -c 100 -f urllist.txt

        With approximately 300-400 hits per second against a dual-core machine, we saw error messages in the log at least every few seconds.

        Show
        Marc Novakowski added a comment - While load testing our application, I think I ran into the race condition mentioned above. The entries in the log file looked something like this: ERROR Exception rendering #parse( /include/leaderboard.vm ) : java.lang.NullPointerException ERROR Exception rendering #parse( /detail/album_layout.vm ) : java.lang.NullPointerException and sometimes: ERROR Template.merge() failure. The document is null, most likely due to parsing error. ERROR VelocityViewServlet: Exception processing the template: java.lang.Exception: Template.merge() failure. The document is null, most likely due to parsing error. We fixed it by turning off the "modificationCheckInterval" (which had been set to 4, it is now set to 0). This workaround is adequate for us, since we don't modify template files on-the-fly in production. But it would be nice to know that the underlying bug is fixed at some point! In order to replicate this race condition, I had to put a lot of simulated load on the server. I used a tool called "siege" with the following arguments: siege -t 1H -i -b -c 100 -f urllist.txt With approximately 300-400 hits per second against a dual-core machine, we saw error messages in the log at least every few seconds.
        Hide
        Nathan Bubna added a comment -

        Ok, i've checked in what should be a fix for the WebappLoader.
        http://svn.apache.org/viewvc?rev=416164&view=rev

        See the latest version at:
        http://svn.apache.org/viewvc/jakarta/velocity/tools/trunk/src/java/org/apache/velocity/tools/view/servlet/WebappLoader.java?view=markup&pathrev=416164

        If one of you guys that is experiencing this bug would be willing to try it out in your setup and confirm whether this resolves things for you, that would be great.

        Show
        Nathan Bubna added a comment - Ok, i've checked in what should be a fix for the WebappLoader. http://svn.apache.org/viewvc?rev=416164&view=rev See the latest version at: http://svn.apache.org/viewvc/jakarta/velocity/tools/trunk/src/java/org/apache/velocity/tools/view/servlet/WebappLoader.java?view=markup&pathrev=416164 If one of you guys that is experiencing this bug would be willing to try it out in your setup and confirm whether this resolves things for you, that would be great.
        Nathan Bubna made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Hide
        Stu Belden added a comment -

        The fix above resolves the issue for me.

        This issue: VELOCITY-383 seems like a good place to discuss the Template thread safety issue.

        Show
        Stu Belden added a comment - The fix above resolves the issue for me. This issue: VELOCITY-383 seems like a good place to discuss the Template thread safety issue.

          People

          • Assignee:
            Nathan Bubna
            Reporter:
            Stu Belden
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development