Javalite framework - problem with locating existing FreeMarker templates

Question

I am developing a simple web application which provides RestFul API for managing several resources.

I am using java standard edition - openjdk version "1.8.0_191 and the following javalite dependencies:

javalite-common-2.3-SNAPSHOT.jar
activejdbc-2.3-SNAPSHOT.jar
activeweb-2.3-SNAPSHOT.jar
activeweb-testing-2.3-SNAPSHOT.jar
freemarker-2.3.28.jar

I use embedded jetty v9.4.1 for web server and the whole project is packed as jar with dependencies and is run using the following command:

java -Dconfig=/etc/project/config.properties -jar jarname.jar

The web application is designed to serve only JSON and all FreeMarker templates construct json messages. Here is my FreeMarker config class:

public class FreeMarkerConfig extends AbstractFreeMarkerConfig {
    @Override
    public void init() {
        // this is to override a strange FreeMarker default processing of numbers
        Configuration config = this.getConfiguration();
        config.setNumberFormat("0.##");

        config.setClassicCompatible(true);
        config.setClassForTemplateLoading(this.getClass(), "webapp/WEB-INF/views");
    }
}

After the packaging the structure inside the jar is as follows (this is a simplified version with only one resource):

├── META-INF
│   ├── MANIFEST.MF
│   └── maven
│       └── project.control
│           └── panel
│               ├── pom.properties
│               └── pom.xml
├── activejdbc_models.properties
├── app
│   ├── config
│   │   ├── AppBootstrap.class
│   │   ├── AppControllerConfig.class
│   │   ├── DbConfig.class
│   │   ├── FreeMarkerConfig.class
│   │   └── RouteConfig.class
│   ├── controllers
│   │   ├── APIController.class
│   │   ├── CatchAllFilter.class
│   │   ├── OfficesController.class
│   └── models
│       ├── Office.class
├── config.properties
├── project
│   └── control
│       └── panel
│           ├── Launcher.class
│           ├── dao
│           │   ├── query
│           │   │   ├── Query.class
│           │   │   ├── QueryBuilder.class
│           │   │   ├── QueryStringBuilder.class
│           │   │   ├── StatsParamsHandler.class
│           │   └── validators
│           │       ├── OfficeValidator.class
│           ├── exceptions
│           │   └── ResourceNotFoundException.class
│           └── util
│               ├── Config.class
│               ├── JsonHelper.class
└── webapp
    └── WEB-INF
        ├── views
        │   ├── offices
        │   │   ├── _comma.ftl
        │   │   ├── _office.ftl
        │   │   ├── _office_agency.ftl
        │   │   ├── _office_agent.ftl
        │   │   └── index.ftl
        │   ├── layouts
        │   │   └── default_layout.ftl
        │   ├── shared
        │   │   ├── _paging.ftl
        │   │   └── message.ftl
        │   ├── system
        │   │   ├── 404.ftl
        │   │   └── error.ftl
        └── web.xml

Most of the time everything seems to operate normally and without any problems. But at some point something happens and FreeMarker is unable to locate the templates which were previously served multiple times.

I am not able to reproduce the behaviour on localhost so I am not able to debug it.

It happened several times while running on a server. The only observation I had is that it happens after several idle hours - i.e there were no requests for several hours, the next request fails because FreeMarker can't locate the needed template. Here is the exact exception which is thrown, when /offices is requested:


2019-06-24 15:22:50 - INFO  LazyList:164 - {"sql":"SELECT * FROM offices  ORDER BY id  LIMIT 20  OFFSET 0 ","params":[],"duration_millis":2,"cache":"miss"}
2019-06-24 15:22:50 - INFO  DB:164 - {"sql":"SELECT COUNT(*) FROM offices","params":[],"duration_millis":0}
2019-06-24 15:22:50 - INFO  FreeMarkerTemplateManager:81 - Rendering template: '/offices/index.ftl' without layout.
2019-06-24 15:22:50 - INFO  FreeMarkerTemplateManager:81 - Rendering template: '/shared/message.ftl' without layout.
2019-06-24 15:22:50 - INFO  RequestDispatcher:360 - {"controller":"app.controllers.OfficesController","duration_millis":15,"remote_ip":"127.0.0.1","method":"GET","action":"index","error":"Failed to render template: '/shared/message.ftl' without layout.  Template not found for name \\\"/shared/message.ftl\\\".\\nThe name was interpreted by this TemplateLoader: WebappTemplateLoader(subdirPath=\\\"/WEB-INF/views/\\\", servletContext={contextPath=\\\"\\\", displayName=\\\"activeweb\\\"}).","url":"http://127.0.0.1:5050/offices","status":404}
2019-06-24 15:22:50 - INFO  FreeMarkerTemplateManager:81 - Rendering template: '/system/404.ftl' with layout: '/layouts/default_layout.ftl'.
2019-06-24 15:22:50 - ERROR RequestDispatcher:290 - ActiveWeb internal error:
org.javalite.activeweb.ViewMissingException: Failed to render template: '/system/404.ftl' with layout: '/layouts/default_layout.ftl'.  Template not found for name "/system/404.ftl".
The name was interpreted by this TemplateLoader: WebappTemplateLoader(subdirPath="/WEB-INF/views/", servletContext={contextPath="", displayName="activeweb"}).
  at org.javalite.activeweb.freemarker.FreeMarkerTemplateManager.merge(FreeMarkerTemplateManager.java:109)
  at org.javalite.activeweb.RenderTemplateResponse.doProcess(RenderTemplateResponse.java:88)
  at org.javalite.activeweb.ControllerResponse.process(ControllerResponse.java:67)
  at org.javalite.activeweb.RequestDispatcher.renderSystemError(RequestDispatcher.java:283)
  at org.javalite.activeweb.RequestDispatcher.doFilter(RequestDispatcher.java:219)
  at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1613)
  at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:541)
  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
  at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
  at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1584)
  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
  at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1228)
  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
  at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:481)
  at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
  at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1130)
  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
  at org.eclipse.jetty.server.Server.handle(Server.java:564)
  at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
  at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
  at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
  at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:112)
  at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
  at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
  at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
  at java.lang.Thread.run(Thread.java:748)

Additional details can be provided in case of need.

What may cause such problems - while everything seems operational, suddenly FreeMaker can't locate templates which were previously served without any problems.

Any suggestions that may help for debugging the issue will be appreciated.

Thanks!

this is probably related to Freemarker more than JavaLite. In 10 years building JavaLite - based systems we never encountered that a view just disappears from runtime. However, we also never ran JavaLite embedded in Jetty. Can you please experiment and deploy it as a WAR file on Tomcat and run for a while to see if you encounter this issue? At least you will eliminate the embedded Jetty - maybe Freemarker is not feeling all that well there. Another thing you can look at is to see if Jetty is expanding files from WAR file to a file system and somehow cleans them out? — ipolevoy, Jun 25 '19 at 16:17
Why don't you add debug logging into your app that would log where the templates actually come from when it works, so that you can manually check that files are still there when you get the error. Another crazy idea, maybe jetty expands the war file into a temp directory that deletes files? — ipolevoy, Jun 25 '19 at 21:23
Note that your FreeMarker configuration was apparently overwritten, as the actual `TemplateLoader` is a `WebappTemplateLoader` (from the error message), not a `ClassTemplateLoader` that you have configured. But of course that doesn't explain why the app breaks... (As @ipolevoy said, it's often that the `tmp` dir is cleared by a scheduled job.) — ddekany, Jun 25 '19 at 22:48
@ipolevoy, @ddekany your comments were really helpful. A quick run with DEBUG level logging showed me that the templates are served from a folder in `/tmp` looking like this: `/tmp/jetty-0.0.0.0-5050-webapp-_-any-1900243345654889594.dir`. It appeared that the server where the project is running has a cleaning policy for the `/tmp` folder which was deleting the templates. Configuring the `tempDirectory` of the `WebAppContext` to store the files outside `/tmp` solved the issue. Thank you! — hpeev, Jun 26 '19 at 10:23

score 2 · Accepted Answer · answered Jun 26 '19 at 11:37

After more detailed investigation it appeared that jetty extracts the FreeMarker templates from the jar and places them in /tmp folder. The folder has the following pattern

/tmp/jetty-<host>-<port>-<resourceBase>-<context>-<virtualhost>-<randomdigits>.dir

Example: jetty-0.0.0.0-5050-webapp-_-any-35239075401795634.dir

Unix based operation systems have policy for cleaning /tmp folder and after the folder is deleted - obviously the templates can't be found.

The solutions is to configure jetty's WebAppContext to use another directory for this kind of data. This can be done with setTempDirectory method:

String webViewsPath = Launcher.class.getResource("/webapp").toString();
WebAppContext webapp = new WebAppContext(webViewsPath, "/");
webapp.setTempDirectory(new File("/data/templates"));
server.setHandler(webapp);

More information for jetty's temporary directories can be found here: https://www.eclipse.org/jetty/documentation/9.4.x/ref-temporary-directories.html

Javalite framework - problem with locating existing FreeMarker templates

1 Answers1