0

Setup, Play 1.2.4 with Morphia 1.2.6a and a MongoDB on MongoLab (not via add-on)

UPDATE Look to bottom of question for explanation.

Running on my local box in Prod and play serves pages with no errors. Pushed up to heroku and the database is throwing below. Other than any database transactions, play is working fine.

2012-03-30T23:17:57+00:00 app[web.1]: Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:27)
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.readMappedField(Mapper.java:501)
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDb(Mapper.java:484)
2012-03-30T23:17:57+00:00 app[web.1]:   ... 18 more
2012-03-30T23:17:57+00:00 app[web.1]: Caused by: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-30T23:17:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:128)
2012-03-30T23:17:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:122)
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:25)
2012-03-30T23:17:57+00:00 app[web.1]:   ... 20 more
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.converters.ObjectIdConverter.decode(ObjectIdConverter.java:28)
2012-03-30T23:17:57+00:00 app[web.1]:   at com.google.code.morphia.converters.DefaultConverters.fromDBObject(DefaultConverters.java:129)

I am using Long for my Id's if that has anything to do with it, play config morphia.id.type=Long

At this point, I'm stuck. Any help, greatly appreciated.

Application.conf # configure database name. Default value: test

%prod.morphia.db.name=asdf
%prod.morphia.db.seeds=ds032747.mongolab.com:32747
%prod.morphia.db.username=admin@bla.com
%prod.morphia.db.password=bla
%prod.morphia.id.type=Long

Here is the web app stack from heroku:

2012-03-31T13:14:57+00:00 app[web.1]: java.lang.RuntimeException: java.lang.RuntimeException: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDb(Mapper.java:487)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDBObject(Mapper.java:267)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.MorphiaIterator.convertItem(MorphiaIterator.java:66)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.MorphiaIterator.processItem(MorphiaIterator.java:53)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.MorphiaIterator.next(MorphiaIterator.java:48)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.QueryImpl.get(QueryImpl.java:365)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.modules.morphia.Model$MorphiaQuery.get(Model.java:1302)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.modules.morphia.Model$MorphiaQuery.first(Model.java:1237)
2012-03-31T13:14:57+00:00 app[web.1]:   at controllers.DataUserService.find(DataUserService.java:30)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.UserService.find(UserService.java:96)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.providers.UsernamePasswordProvider.doAuth(UsernamePasswordProvider.java:71)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.IdentityProvider.authenticate(IdentityProvider.java:67)
2012-03-31T13:14:57+00:00 app[web.1]:   at controllers.securesocial.SecureSocial.authenticate(SecureSocial.java:198)
2012-03-31T13:14:57+00:00 app[web.1]:   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2012-03-31T13:14:57+00:00 app[web.1]:   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
2012-03-31T13:14:57+00:00 app[web.1]:   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:548)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.lang.reflect.Method.invoke(Method.java:616)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invoke(ActionInvoker.java:502)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:478)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:473)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invoke(ActionInvoker.java:161)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.server.PlayHandler$NettyInvocation.execute(PlayHandler.java:257)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.Invoker$Invocation.run(Invoker.java:278)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.server.PlayHandler$NettyInvocation.run(PlayHandler.java:235)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.FutureTask.run(FutureTask.java:166)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
2012-03-31T13:14:57+00:00 app[web.1]:   at java.lang.Thread.run(Thread.java:636)
2012-03-31T13:14:57+00:00 app[web.1]: Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:27)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.readMappedField(Mapper.java:501)
2012-03-31T13:14:57+00:00 app[web.1]:   ... 32 more
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDb(Mapper.java:484)
2012-03-31T13:14:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:128)
2012-03-31T13:14:57+00:00 app[web.1]: Caused by: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.converters.ObjectIdConverter.decode(ObjectIdConverter.java:28)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.converters.DefaultConverters.fromDBObject(DefaultConverters.java:129)
2012-03-31T13:14:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:122)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:25)
2012-03-31T13:14:57+00:00 app[web.1]:   ... 34 more
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDBObject(Mapper.java:267)
2012-03-31T13:14:57+00:00 app[web.1]: 13:14:57,854 ERROR ~ Error authenticating user
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.MorphiaIterator.convertItem(MorphiaIterator.java:66)
2012-03-31T13:14:57+00:00 app[web.1]: java.lang.RuntimeException: java.lang.RuntimeException: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDb(Mapper.java:487)
2012-0
3-31T13:14:57+00:00 app[web.1]:     at com.google.code.morphia.query.MorphiaIterator.next(MorphiaIterator.java:48)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.MorphiaIterator.processItem(MorphiaIterator.java:53)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.query.QueryImpl.get(QueryImpl.java:365)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.modules.morphia.Model$MorphiaQuery.get(Model.java:1302)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.UserService.find(UserService.java:96)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.modules.morphia.Model$MorphiaQuery.first(Model.java:1237)
2012-03-31T13:14:57+00:00 app[web.1]:   at controllers.DataUserService.find(DataUserService.java:30)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.providers.UsernamePasswordProvider.doAuth(UsernamePasswordProvider.java:71)
2012-03-31T13:14:57+00:00 app[web.1]:   at securesocial.provider.IdentityProvider.authenticate(IdentityProvider.java:67)
2012-03-31T13:14:57+00:00 app[web.1]:   at controllers.securesocial.SecureSocial.authenticate(SecureSocial.java:198)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:548)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invoke(ActionInvoker.java:502)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:478)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invoke(ActionInvoker.java:161)
2012-03-31T13:14:57+00:00 app[web.1]:   at Invocation.HTTP Request(Play!)
2012-03-31T13:14:57+00:00 app[web.1]:   at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:473)
2012-03-31T13:14:57+00:00 app[web.1]: Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:27)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.readMappedField(Mapper.java:501)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.Mapper.fromDb(Mapper.java:484)
2012-03-31T13:14:57+00:00 app[web.1]:   ... 18 more
2012-03-31T13:14:57+00:00 app[web.1]: Caused by: java.lang.IllegalArgumentException: invalid ObjectId [4]
2012-03-31T13:14:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:128)
2012-03-31T13:14:57+00:00 app[web.1]:   at org.bson.types.ObjectId.<init>(ObjectId.java:122)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.converters.ObjectIdConverter.decode(ObjectIdConverter.java:28)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.converters.DefaultConverters.fromDBObject(DefaultConverters.java:129)
2012-03-31T13:14:57+00:00 app[web.1]:   at com.google.code.morphia.mapping.ValueMapper.fromDBObject(ValueMapper.java:25)
2012-03-31T13:14:57+00:00 app[web.1]:   ... 20 more

Strange that it runs (play run --%prod) on my box using the same mongolab db but fails on Heroku. Heroku logs are rounded to the second - not much help. I wonder if Heroku is overriding with custom driver?? Heroku has an "add-on" offering of MongoLab and I suspect that has something to do with it, but that is a stab in the dark.

I'm going to try a test with Heroku mongolab add-on and see if that works. It's a pain since I already have a db, but worth a try - I think.

Pulled down a clone from heroku and ran play deps --sync, ran without errors locally.

Looks suspiciously like this issue with application versions (on node). I hope this is not a wild goose chase.

Fixed. Here's the deal. Heroku does not like framework IDs I have at minimum three separate framework ids set up for local testing and two different db providers. One of them was set to my prod (%prod.). Heroku does not like these. Eliminate all prefixed framework ids on config (I had to comment out all other db's) and bang, works like a charm. I think heroku needs to work on their config parser.

It's the Framework ID setting in eclipse. Found that after rebuilding my development box, that this problem resurfaced. I noticed that running play from the command line with the framework argument included resulted in no errors. Did a bit more research and found that the Play eclipsify command overwrites the build configurations (my IDE is eclipse). The newly generated configurations "VM arguments" do not include a framework id value "-Dplay.id=" (it's blank). I changed this value to "-Dplay.id=dev" for my dev launcher and Play processes the config correctly. Heroku passes the framework id --%prod by default in PLAY_OPTS so now both environments are working as expected.

I'm updating this question for the sake of others who may have a similar issue. I also found this comment that reinforces this https://stackoverflow.com/a/9211118/1193291

Community
  • 1
  • 1
zenoexo
  • 49
  • 7
  • can you post relevant part of your application.conf? – Gelin Luo Mar 31 '12 at 02:07
  • I've just updated with the morphia conf section. The "invalid ObjectId [4]" from stack trace above is the Long Id for record I was after. Any thoughts why heroku is not identical. My local is hitting the exact same db on mongolab with no error. – zenoexo Mar 31 '12 at 02:38
  • 1
    looks good. Did you notice any other bad signals in your log file? – Gelin Luo Mar 31 '12 at 11:42
  • Nothing else looks out of the ordinary to me. – zenoexo Mar 31 '12 at 13:20
  • Added all stack from Heroku's web app logger. – zenoexo Mar 31 '12 at 13:48
  • Well, I ran the test on Heroku's mongolab "add-on" db with exact same result. Looks like a playmorphia or morphia issue to me. – zenoexo Mar 31 '12 at 14:43
  • I need to get this out the door, so, I just made a war and deployed on the Amazon beanstalk container. It works there, but I would love to know what is wrong with Heroku. I just sent them a support request - they don't work weekends :( – zenoexo Mar 31 '12 at 20:30
  • I tested this out and it worked fine for me as long as the collection was created when the `morphia.id.type=Long` was set. You can find my test app at: https://github.com/jamesward/playmongo/tree/long_id – James Ward Apr 03 '12 at 15:56
  • Hmm. I need your pull request accepted for play-morphia to support the morphia.url for heroku. – zenoexo Apr 04 '12 at 22:20
  • OK, finally got it running on Heroku. I've updated the question with my fix. Looks like a Heroku play config parser / interpreter problem to me. Test by adding more than one mongo config with different framework id's, and it will error. This does not happen on local box, or in the elastic beanstalk container. – zenoexo Apr 05 '12 at 02:36
  • If you have the same version of the JDK locally then this shouldn't run any differently on Heroku. Heroku uses OpenJDK 6. Can you fork my playmongo project and recreate the error within that project? – James Ward Apr 06 '12 at 12:59
  • Thanks @JamesWard. Add some framework ids other than '%prod.' e.g. Prefix '%dev.' to your non-production morphia config lines and you should see the failure. Sorry, I don't want to create a faux account on heroku/mongo just for this test. BTW: jre6. Forked [link](https://github.com/zenoexo/playmongo) – zenoexo Apr 10 '12 at 15:13
  • For some reason it doesn't work to set `morphia.id.type` for each environment. But it works to set it generally: https://github.com/jamesward/playmongo/commit/340a85ee81ff615f7e0b8165af2e8ebff40babc8 – James Ward Apr 12 '12 at 02:59
  • Yup. Thanks for the independent test. Any reason why this is unique to heroku? The code does work locally, and in a container. I'll update my heroku support ticket with your answer. – zenoexo Apr 12 '12 at 20:42
  • I was able to reproduce locally but I'm on OpenJDK on Ubuntu which is a similar environment as Heroku. So perhaps it's an OpenJDK bug. – James Ward Apr 16 '12 at 11:58

2 Answers2

0

It's the Framework ID setting in eclipse. Found that after rebuilding my development box, that this problem resurfaced. I noticed that running play from the command line with the framework argument included resulted in no errors. Did a bit more research and found that the Play eclipsify command overwrites the build configurations (my IDE is eclipse). The newly generated configurations "VM arguments" do not include a framework id value "-Dplay.id=" (it's blank). I changed this value to "-Dplay.id=dev" for my dev launcher and Play processes the config correctly. Heroku passes the framework id --%prod by default in PLAY_OPTS so now both environments are working as expected.

I'm updating this question for the sake of others who may have a similar issue. I also found this comment that reinforces this https://stackoverflow.com/a/9211118/1193291

Community
  • 1
  • 1
zenoexo
  • 49
  • 7
0

I assume this is for Play version 1. I was experiencing this locally. If anyone else gets this, this will fix it:

play clean

Then restart play.

Fred Campos
  • 1,457
  • 1
  • 19
  • 22