Issue with Objectify 5.1.x

[tomohiro-n]

Hi,

I cloned the latest release tag ninja-appengine-1.9.23 and ran ninja-appengine-integration-test-blog project with a maven command mvn appengine:devserver -Pdevserver, but observed an error below.

Caused by: java.lang.IllegalStateException: You have not started an Objectify context. You are probably missing the ObjectifyFilter. If you are not running in the context of an http request, see the ObjectifyService.run() method.

Actually I've seen the same issue before with Objectify 5.1.x.
At the time I didn't use Ninjaframework and started seeing this issue since upgrading from 5.0.x.

There's a relevant post in Stack Overflow.
http://stackoverflow.com/questions/26577029/objectify-5-1-context-not-started-error-due-to-missing-objectifyfilter

Questions

1. Isn't there anyone seeing this issue with the sample here?
2. Does anyone know if there is a critical impact if I downgrade to 5.0.x and use it along with the latest ninja-appengine?

The detailed stacktrace is below.

Thanks,
Tomo

[INFO] 19:08:01.223 [main] INFO  ninja.lifecycle.LifecycleServiceImpl - Starting Ninja application...
[INFO] Sep 14, 2015 7:08:01 PM com.google.apphosting.utils.jetty.JettyLogger warn
[INFO] WARNING: Failed startup of context com.google.appengine.tools.development.DevAppEngineWebAppContext@50029372{/,/Users/xxx/yyy/ninja-appengine/ninja-appengine-integration-test-blog/target/ninja-appengine-integration-test-blog-1.9.23}
[INFO] ninja.lifecycle.FailedStartException: java.lang.ExceptionInInitializerError
[INFO]  at ninja.lifecycle.LifecycleRegister.invokeTarget(LifecycleRegister.java:103)
[INFO]  at ninja.lifecycle.LifecycleRegister.start(LifecycleRegister.java:55)
[INFO]  at ninja.lifecycle.LifecycleServiceImpl.start(LifecycleServiceImpl.java:84)
[INFO]  at ninja.NinjaDefault.onFrameworkStart(NinjaDefault.java:142)
[INFO]  at ninja.servlet.NinjaBootstrap.boot(NinjaBootstrap.java:93)
[INFO]  at ninja.servlet.NinjaServletListener.createNinjaBootstrap(NinjaServletListener.java:134)
[INFO]  at ninja.servlet.NinjaServletListener.getInjector(NinjaServletListener.java:110)
[INFO]  at com.google.inject.servlet.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:47)
[INFO]  at ninja.servlet.NinjaServletListener.contextInitialized(NinjaServletListener.java:62)
[INFO]  at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:548)
[INFO]  at org.mortbay.jetty.servlet.Context.startContext(Context.java:136)
[INFO]  at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1250)
[INFO]  at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517)
[INFO]  at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467)
[INFO]  at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
[INFO]  at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
[INFO]  at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
[INFO]  at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
[INFO]  at org.mortbay.jetty.Server.doStart(Server.java:224)
[INFO]  at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
[INFO]  at com.google.appengine.tools.development.JettyContainerService.startContainer(JettyContainerService.java:266)
[INFO]  at com.google.appengine.tools.development.AbstractContainerService.startup(AbstractContainerService.java:288)
[INFO]  at com.google.appengine.tools.development.AutomaticInstanceHolder.startUp(AutomaticInstanceHolder.java:26)
[INFO]  at com.google.appengine.tools.development.AbstractModule.startup(AbstractModule.java:87)
[INFO]  at com.google.appengine.tools.development.Modules.startup(Modules.java:105)
[INFO]  at com.google.appengine.tools.development.DevAppServerImpl.doStart(DevAppServerImpl.java:258)
[INFO]  at com.google.appengine.tools.development.DevAppServerImpl.access$000(DevAppServerImpl.java:47)
[INFO]  at com.google.appengine.tools.development.DevAppServerImpl$1.run(DevAppServerImpl.java:213)
[INFO]  at com.google.appengine.tools.development.DevAppServerImpl$1.run(DevAppServerImpl.java:211)
[INFO]  at java.security.AccessController.doPrivileged(Native Method)
[INFO]  at com.google.appengine.tools.development.DevAppServerImpl.start(DevAppServerImpl.java:211)
[INFO]  at com.google.appengine.tools.development.DevAppServerMain$StartAction.apply(DevAppServerMain.java:270)
[INFO]  at com.google.appengine.tools.util.Parser$ParseResult.applyArgs(Parser.java:48)
[INFO]  at com.google.appengine.tools.development.DevAppServerMain.run(DevAppServerMain.java:218)
[INFO]  at com.google.appengine.tools.development.DevAppServerMain.main(DevAppServerMain.java:209)
[INFO] Caused by: java.lang.ExceptionInInitializerError
[INFO]  at java.lang.Class.forName0(Native Method)
[INFO]  at java.lang.Class.forName(Class.java:264)
[INFO]  at com.google.appengine.tools.development.agent.runtime.RuntimeHelper.checkRestricted(RuntimeHelper.java:70)
[INFO]  at com.google.appengine.tools.development.agent.runtime.Runtime.checkRestricted(Runtime.java:65)
[INFO]  at conf.StartupActions.generateDummyDataWhenInTest(StartupActions.java:26)
[INFO]  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[INFO]  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[INFO]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[INFO]  at java.lang.reflect.Method.invoke(Method.java:497)
[INFO]  at com.google.appengine.tools.development.agent.runtime.Runtime.invoke(Runtime.java:130)
[INFO]  at ninja.lifecycle.LifecycleRegister.invokeTarget(LifecycleRegister.java:96)
[INFO]  ... 34 more
[INFO] Caused by: java.lang.IllegalStateException: You have not started an Objectify context. You are probably missing the ObjectifyFilter. If you are not running in the context of an http request, see the ObjectifyService.run() method.
[INFO]  at com.googlecode.objectify.ObjectifyService.ofy(ObjectifyService.java:44)
[INFO]  at conf.ObjectifyProvider.setup(ObjectifyProvider.java:52)
[INFO]  at conf.ObjectifyProvider.<clinit>(ObjectifyProvider.java:44)
[INFO]  ... 45 more
[INFO] 

[raphaelbauer]

I am seeing the same problems fwiw...

[tomohiro-n]

@raphaelbauer thank you for the comment.
I did the following to make it work.

1. Downgraded Objectify to 5.0.5
2. Rolled back 5256d2e for test cases as required
3. (Though I assume this is necessary regardless of whether 5.0.x or 5.1.x) made a few lines of change in ArticleDao because filter method did not work with Id fields

For now, I'll go with this. I'm not really sure if you officially want to downgrade as I did or to make some proper fixes to keep using the latest Objectify.

Any feedbacks would be appreciated.

Thanks,
Tomo

[JesseTG]

Any resolution? I really can't use Ninja if I can't get a simple archetype working.

[raphaelbauer]

Hi Jesse

make sure your StartupActions class looks like:

@Start(order=100)
public void generateDummyDataWhenInTest() {
    if (ninjaProperties.isDev()) {
        try (Closeable closeable = ObjectifyService.begin()) {
            ObjectifyProvider.setup();
        } catch (IOException ex) {
            Logger.getLogger(StartupActions.class.getName()).log(Level.SEVERE, null, ex);
        } 
    }
}

We should have fixed that long ago in the archetype, but it's not really high on the prio list. It would be awesome if you could push a PR :)

[raphaelbauer]

Fixed in ninja-appengine 1.9.31. Please confirm and close this issue after trying the fix. Thanks!

[JesseTG]

@raphaelbauer No luck, ObjectifyService.begin() doesn't exist.

Having said that, I have no idea what I'm doing.

[raphaelbauer]

Okay... here's the thing. When we release a new archtype version it takes around one week until a simple command like

mvn archetype:generate -DarchetypeGroupId=org.ninjaframework -DarchetypeArtifactId=ninja-appengine-blog-archetype -DarchetypeVersion=1.9.31

"sees" the new archetype. Afaics the new version is not yet listed in Maven's archtype registry.

I bet you are still getting version 1.9.30 when calling the archetype - right? Therefore you still see the bug...

I'll wait some more days and will then ping sonatype - maybe something went wrong during publishing of the archetype.

You can still manually update your pom.xml to use Ninja 5.2.2 and GAE 1.9.31 + add the workaround described above - that will fix the issue....

[JesseTG]

OK, and which version of Objectify do I use? 5.0.5? Because now it seems the API's changed; I don't see an ObjectifyService.begin() anywhere.

[raphaelbauer]

Btw I created an issue. Let's see where the problem is: https://issues.sonatype.org/browse/OSSRH-20511

[raphaelbauer]

Objectify should be 5.1.9 / ninja-appengine should be 1.9.31. And your project file should roughly look like: https://github.com/ninjaframework/ninja-appengine/blob/master/ninja-appengine-blog-archetype/src/main/resources/archetype-resources/pom.xml

Sorry for the inconveniences... Wouldn't be such a hassle with an archetype :)