Missing macros.vm file causes Butterfly to fallback on controller.js of the main application

[wetneb]

When running OpenRefine 3.8.1 with the Commons extension 0.1.0 0.1.1, we get an error because of a missing macros.vm file:

10:15:55.802 [                 velocity]  Velocimacro : Velocimacro : Error using VM library : macros.vm (0ms)
org.apache.velocity.exception.ResourceNotFoundException: Unable to find resource 'macros.vm'
	at org.apache.velocity.runtime.resource.ResourceManagerImpl.loadResource(ResourceManagerImpl.java:483)
	at org.apache.velocity.runtime.resource.ResourceManagerImpl.getResource(ResourceManagerImpl.java:354)
	at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1400)
	at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1380)
	at org.apache.velocity.runtime.VelocimacroFactory.initVelocimacro(VelocimacroFactory.java:202)
	at org.apache.velocity.runtime.RuntimeInstance.init(RuntimeInstance.java:261)
	at org.apache.velocity.runtime.RuntimeInstance.init(RuntimeInstance.java:589)
	at org.apache.velocity.app.VelocityEngine.init(VelocityEngine.java:135)
	at edu.mit.simile.butterfly.Butterfly.configureModules(Butterfly.java:862)
	at edu.mit.simile.butterfly.Butterfly.configure(Butterfly.java:428)
	at edu.mit.simile.butterfly.Butterfly.init(Butterfly.java:295)
	at org.eclipse.jetty.servlet.ServletHolder$Wrapper.init(ServletHolder.java:1305)
	at org.eclipse.jetty.servlet.ServletHolder.initServlet(ServletHolder.java:633)
	at org.eclipse.jetty.servlet.ServletHolder.getServlet(ServletHolder.java:486)
	at org.eclipse.jetty.servlet.ServletHolder.prepare(ServletHolder.java:731)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:524)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at com.google.refine.ValidateHostHandler.handle(ValidateHostHandler.java:93)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
	at org.eclipse.jetty.server.Server.handle(Server.java:563)
	at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)

This error is displayed in the logs and does not halt the further initialization of the Commons extension as a Butterfly module.
Curiously enough, it seems that the Commons extension then gets initialized but with the wrong controller.js file: the ./main/webapp/modules/core/MOD-INF/controller.js file in OpenRefine is run for the Commons extension, re-registering all the main components as if they belonged to the Commons extension.
This, in turn, causes OpenRefine/CommonsExtension#120 because it registers a second copy of suggest-4_3a.js in the project-bundle.js.

[sebastian-berlin-wmse]

Interesting. I tested adding an empty module/macros.vm and that looks to have solved both OpenRefine/CommonsExtension#120 and OpenRefine/OpenRefine#6581. At least the immediate issues, reconciliation not loading and source for Commons missing, respectively.

[thadguidry]

This error is displayed in the logs and does not halt the further initialization of the Commons extension as a Butterfly module.

@wetneb This was a common thing in the early days of the extension mechanism and David fixed it by forcing the exception to always display on the browser and not load the Project index page (that's how I recall it working in 2.7 I think). Somehow that has changed over the years or recently?

@tfmorris This is what I was referring to that if 1 extension doesn't load... show that on the browser...and halt and do not bother loading additional extensions or OpenRefine core (this used to work that way before some time ago, maybe 2.7? dunno). Anyways, this will let users know something is up with an extension loading and they can choose to disable/uninstall it/report it to us or the maintainer.

[tfmorris]

Does the error also occur with the latest CommonsExtension 0.1.1?

[wetneb]

Yes sorry that's a typo on my part, I meant 0.1.1.

[tfmorris]

It appears that the behavior of Velocity changed sometime between 1.5 and 1.6.3. This init() call:

simile-butterfly/main/src/edu/mit/simile/butterfly/Butterfly.java

Line 862 in 32caedc

velocity.init(properties);

can now throw an exception where it never did before.

I think maybe the assumption was the the module configure operation couldn't fail, only the initialization could.

We should rework the exception handling (and refactor the big configure method so that it's not so long & deeply nested), but for the immediate issue, this can be fixed in the OpenRefine scope by reverting the Velocity 1.5.

[tfmorris]

Also, any Velocity init() error will cause this failure mode, but this specific problem is a actually bug in the Commons Extension, which was previously hidden by Velocity, where it has a property file entry pointing to a non-existent macro file.