Sporadic DuplicateAttributeNames error during Model enhancement if auto timestamp is enabled

[mgspross]

It seems that Play 1.2.5 doesn't enhance classes in a fixed, guaranteed order. In some cases, this can cause a DuplicateAttributeNames validation error to occur (within Morphia itself) if the auto timestamp feature is turned on.

Specifically, this can happen if you create an entity class A, and a subclass B that extends A (for example, LifeCycle and LifeCycle.Child in the play-morphia unit-tests project).

If the subclass is enhanced before the superclass, the _created and _modified fields get added to the subclass by MorphiaEnhancer, and they will also be added to the superclass.

This creates a problem for Morphia's Mapper class, because it will see these fields on the subclass and on the superclass and throw a ConstraintViolationException because it thinks they are duplicate field declarations.

If the superclass is enhanced before the subclass, this issue doesn't occur, because if the superclass already has these fields, PlayMorphia will not add them to the subclass, and Morphia will therefore only see one copy of these fields.

This issue happens in play-morphia 1.2.12 (which uses morphia-1.00-20110403.jar).

[greenlaw110]

this looks weird. When a class is enhanced, meaning it is already loaded
from the class loader, and if a sub class is loaded from a class loader,
then it's parent class for sure should already been loaded and by that
enhanced.

Do you have a sample can reproduce the error you described?

On Mon, Jan 28, 2013 at 2:14 PM, Mike Spross notifications@github.comwrote:

It seems that Play 1.2.5 doesn't enhance classes in a fixed, guaranteed
order. In some cases, this can cause a DuplicateAttributeNames validation
error to occur (within Morphia itself) if the auto timestamp feature is
turned on.

Specifically, this can happen if you create an entity class A, and a
subclass B that extends A (for example, LifeCycle and _LifeCycle.Child_in the play-morphia
unit-tests project).

If the subclass is enhanced before the superclass, the _created and
*_modified fields get added to the subclass by MorphiaEnhancer, and
they will also be added to the superclass.

This creates a problem for Morphia's Mapper class, because it will see
these fields on the subclass and on the superclass and throw a *
ConstraintViolationException* because it thinks they are duplicate field
declarations.

If the superclass is enhanced before the subclass, this issue doesn't
occur, because if the superclass already has these fields, PlayMorphia will
not add them to the subclass, and Morphia will therefore only see one copy
of these fields.

This issue happens in play-morphia 1.2.12 (which uses
morphia-1.00-20110403.jar).

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/103.

[mgspross]

I thought it was strange as well, and I assumed the same thing (that the classloader would load the parent class before the subclass, so it should be enhanced before the subclass).

It started happening to me "all of a sudden" on my fork of the project: I thought one of my code changes was causing the problem, but now I am not so sure, because I could see from the Play application logs that LifeCycle$Child was being enhanced before LifeCycle when I ran the unit-tests project.

For me, the issue was happening with the LifeCycle.Child inner class in samples-and-tests\unit-tests: it kept getting enhanced before the parent LifeCycle class, but this wasn't happening for me earlier when I originally pulled your code. I moved this class into a separate file and renamed to LifeCycleChild, and still had the problem. It only went away when I renamed the class to ALifeCycleChild - that was just a lucky change that happened to work.

I think the problem is that the classloader has -- at least in some cases -- already loaded all of the classes when Play runs the class enhancers: therefore, I think the classes are enhanced in whatever order Play stores the classes in the play.Play.classes; however, that is just a guess based on what I saw in the logs.

I ran play clean to make sure Play re-compiled and re-enhanced the classes each time.

I would like to try to reproduce this with a "clean" copy of your repository, but I am having trouble building the current master branch (in my fork I made some changes so I could build it in my environment, but I would like to try with the current code in master to verify that it's not just my fork that has this problem).

I tried this:

$ git clone https://github.com/greenlaw110/play-morphia.git
$ cd play-morphia
$ mvn compile

But I get compile errors related to javassist (I am using play-1.2.5, which uses an older version of javassist [3.9.0GA] compared to what was originally in 1.2.5rc1).

What is the recommended/preferred way to build the code so that I can try to reproduce this issue?

[mgspross]

Also, here is an excerpt from the Play log when I ran my forked version of the code (although I still want to try with the original code), just to demonstrate that the classes are being enhanced in a different order than expected. In this example, I had put LifeCycle.Child into its own file and renamed it to LifeCycleChild, but I had the same problem with the original LifeCycle.java class, with Child as an inner class):

01:41:32,031 INFO  ~ Listening for HTTP on port 9000 (Waiting a first request to start) ...
01:41:49,028 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> reading id type...
01:41:49,029 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> ID Type set to : STRING
01:41:49,041 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> enhancing models.NewLifeCycle ...
01:41:49,224 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> enhancing CloudTest$Post ...
01:41:49,321 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> enhancing models.AutoTs ...
01:41:49,408 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> enhancing models.LifeCycleChild ...
01:41:49,548 DEBUG ~ MorphiaPlugin-1.2.13mt_alpha2> enhancing models.LifeCycle ...

For some reason, models.LifeCycleChild is enhanced before models.LifeCycle. This causes the error I mentioned in the bug report to occur later when the subclass is mapped by Morphia:

play.exceptions.UnexpectedException: Unexpected Error
    at play.Play.start(Play.java:556)
    at play.Play.detectChanges(Play.java:630)
    at play.Invoker$Invocation.init(Invoker.java:198)
    at Invocation.HTTP Request(Play!)
Caused by: java.lang.RuntimeException: com.google.code.morphia.mapping.validation.ConstraintViolationException: Number of violations: 2
DuplicatedAttributeNames complained about models.LifeCycleChild._created : Mapping to MongoDB field name '_created' is duplicated; you cannot map different java fields to the same MongoDB field.DuplicatedAttributeNames complained about models.LifeCycleChild._modified : Mapping to MongoDB field name '_modified' is duplicated; you cannot map different java fields to the same MongoDB field.

If I change the name of LifeCycleChild to ALifeCycleChild, the error doesn't occur, because in that case LifeCycle is enhanced before ALifeCycleChild, but I am not sure why - I can't see any pattern in the order that Play is loading/enhancing the classes. I think the name change fixed it by coincidence.

This is why I think this has more to do with Play than my fork, but I am curious to see what happens with the master code in your repository here to see if the same issue occurs on my machine. Maybe it has to do with the version of Play and/or the JDK that I have installed. My fork also has some additional classes that I added to the unit-tests project - maybe that it causing the other classes to be loaded in a different order (again, by chance).

I will try a few more things on my end. I'm also researching a bit more about how classloading is supposed to work in Java, to see if it is "normal" for classes to loaded out-of-order.