Velocity could not be initialised! But why?

Hi Guys! I (not very) recently used velocity template engine and came across one of the common issues faced by developers while using the same.

Velocity — Basics & Issue!

Velocity is a Java-based template engine which let’s you reference Java objects in an over simplified manner. My use case was to render a PDF file within a java web application (running within a tomcat container) using static pre-defined templates which are stored in a database. Every aspect of the usage seemed fine until I ran into the following error:

One of the strange observations was, this error occurred only on production boxes and not on my local machine. It took me a long time to replicate the same on my local. Here’s the snippet of the first Velocity Renderer which I wrote.

Quoting the developer guide, “At no time should an application use the internal Runtime, RuntimeConstants, RuntimeSingleton or RuntimeInstance classes in the org.apache.velocity.runtime package, as these are intended for internal use only and may change over time.”

(For in depth details, refer velocity developer guide.)

Figuring out the root cause

Developers (using the legacy pattern) are required to initialise a singleton instance of velocity engine in the JVM (or web app) at runtime. This engine provides the resources (templates), logging, etc to all the velocity users in the JVM. By default, velocity engine initialises with default property set provided via org/apache/velocity/runtime/defaults/velocity.properties file.

With these settings, velocity tries to write a log file named velocity.log in the same directory from where tomcat is started. In case the tomcat server is started from a directory where you (or your user) don’t have write permissions, the initialization of velocity engine will fail.

Replicating the issue on local

In shared components (prod boxes), not all users have all accesses and hence (in my case) restarting tomcat from various directories resulted in the engine initialization failure.

In order to replicate the same issue on my local, I changed the owner of the tomcat directory itself to root. Now the trick here is, if you run your server from tomcat directory, there is no other way but to run it as root user. But this, in turn, won’t replicate the issue for you.

So instead, I ran the tomcat server from my Java IDE IntelliJ. What IntelliJ does for you, is that it overrides the $CATALINA_BASE to a location where it has all the required access. (In case of mac, this path will look something like /Users/jarpit/Library/Caches/IntelliJIdea14/tomcat/Unnamed_Project). Thus all your application log files will be created (in my case, at class load time of log4j’s logger class) in the above directory.

But at runtime, Velocity will try to create the log file in the directory from where IntelliJ had actually started tomcat (which is still the bin folder inside tomcat directory, owned by root user). This results in failure of velocity log file creation and in turn, the engine initialisation failure.

Note: A simpler work around is to create one more user on your local and make it the owner of tomcat directory, instead of root user. Then starting tomcat normally from command line using default $CATALINA_BASE will also result in replication of the issue.

But why the NullPointerExecption?

At first, I thought that the NPE in my logs is because of using velocity’s RuntimeServices directly from my webapp. But turns out, that’s not the case.

A common pattern of initialising singleton instances is to use volatile variables (or syncronized code blocks) and ensure that multiple invocations of init method doesn’t initialise the engine again and again.

Velocity uses two variables to ensure the same.

So, as soon as a thread begins the initialization, initializing is set to true. In between, if some other thread tries to parse a template, it first checks if initialization is required. Now in case, the initialization is on going (initializing being true but initialized being false) and is not finished yet; the code doesn’t break and moves on to get a parser from the parserPool. As the engine is not yet initialized, parserPool actually is null and results in NPE.

How to resolve the same?

Well, the resolution depends on your use case. In my case, the velocity log file is almost redundant. So I revamped the way I had written my VelocityRenderer initially.

Velocity is a helper class which has necessary methods for initialising the velocity engine and utility methods for rendering.

Before initialising the engine, I am now overriding the logging property to no log mode. The remaining properties will still be fetched from the default velocity.property file. In order to parse a template fetched from database, I am using the evaluate method of the same helper class.

In case you still need the velocity log file, you may provide the file path via property runtime.log, or a running instance of logger object using runtime.log.instance or runtime.log.name (more details in velocity developer guide.)

Note: As describe in the “But why the NullPointerExecption?” section, removing the No Log mode property and using the above snippet can still continue to result in NPE.

What Next?

In the next blog, I will try to pen down my results after experimenting with velocity’s performance under load and ways of optimising the same using increased parserPools, etc.