New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Issues with Spring LoadTimeWeaving/Class Transformation on Tomcat 8 #1171
Comments
Also, this is confirmed on Spring 4.1.2.RELEASE with |
Linking to #843 that had very similar problems. We have confirmed that class transformation is being skipped by only using |
Need to test this on 3.1 vs 3.2 to see if this is a problem with Spring 4. |
btw - the error logging is currently reporting some classes that "miss" transformation incorrectly (e.g. FulfillmentBandImpl) |
Yup I'm on that. But why does it report them incorrectly? Why is it 'ok' that those classes are not transformed? |
No idea - just mentioned it because, for example, FulfillmentBandImpl is just a @MappedSuperClass, not an @entity. Some of the other reported are @embeddable. I'm not sure why they're making it in there - I haven't reviewed that code. |
Ah, ok, I was misinterpreting the results from above. Looks like the problem is not with Javassist (surprise surprise). Even though Eclipse was printing out The problem is solely in The really peculiar part of this is that this was not a much larger epidemic. I would think that this would've affected all of our To be clear, this does not fix the original problem. However, I believe we have now confirmed that this issue is not present in 3.1.9. |
…nger has any `@Entity` or `@Table` annotations and is completely benign
…ities underwent class transformation
Moving out of 3.1 to only 3.2. |
I believe that I have narrowed down this problem to EHCache. It appears that, in the background, EHCache is loading ProductImpl and thus hijacking the process by which Tomcat is loading classes and then transforming them. This is the method within Tomcat's protected ResourceEntry findResourceInternal(final String name, final String path)
protected ResourceEntry findResourceInternal(final String name, final String path) {
if (!state.isAvailable()) {
log.info(sm.getString("webappClassLoader.stopped", name));
return null;
}
if (name == null || path == null) {
return null;
}
// This is returning a non-null entry. On every other class that I observed, this returns null and it continues on to the class transformers
ResourceEntry entry = resourceEntries.get(path);
if (entry != null) {
return entry;
}
...
...
// Remaining implementation excluded, but below here is where it loops through the configured `ClassFileTransformer`s I suspect EhCache because my logging looks like this (after change the Tomcat logging to FINE by referencing a logging.properties from Tomcat in Eclipse: http://www.eclipse.org/forums/index.php/t/56855/): ....
....
// Finished transforming ProductAttributeImpl
[SUPPORT] 19:53:39 MultiTenantClassTransformer - MultiTenant-SingleSchema - END - Transform - Copied multi-tenant filter definitions and filters into [org.broadleafcommerce.core.catalog.domain.ProductAttributeImpl]
26-Nov-2014 19:53:39.015 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(org.broadleafcommerce.core.catalog.domain.ProductAttribute, false)
26-Nov-2014 19:53:39.015 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:53:39.016 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(org.broadleafcommerce.core.catalog.domain.ProductAttribute)
26-Nov-2014 19:53:39.016 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:53:39.016 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:53:40.254 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(net.sf.ehcache.store.disk.DiskStore$KeySet, false)
26-Nov-2014 19:53:40.254 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:53:40.254 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(net.sf.ehcache.store.disk.DiskStore$KeySet)
26-Nov-2014 19:53:40.415 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:53:40.415 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(net.sf.ehcache.store.disk.DiskStore$KeyIterator, false)
26-Nov-2014 19:53:40.415 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:53:40.415 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(net.sf.ehcache.store.disk.DiskStore$KeyIterator)
26-Nov-2014 19:53:40.428 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(net.sf.ehcache.store.disk.DiskStore$HashIterator, false)
26-Nov-2014 19:53:40.428 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:53:40.428 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(net.sf.ehcache.store.disk.DiskStore$HashIterator)
26-Nov-2014 19:53:40.440 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:53:40.440 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:53:40.441 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(net.sf.ehcache.store.disk.Segment$HashIterator, false)
26-Nov-2014 19:53:40.441 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:53:40.441 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(net.sf.ehcache.store.disk.Segment$HashIterator)
26-Nov-2014 19:53:40.454 FINE [generated%0052esource%0043ache.data] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Loading class from local repository
26-Nov-2014 19:55:52.294 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(org.broadleafcommerce.core.catalog.domain.ProductImpl, false)
26-Nov-2014 19:55:52.294 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.loadClass Searching local repositories
26-Nov-2014 19:55:52.294 FINE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.findClass findClass(org.broadleafcommerce.core.catalog.domain.ProductImpl)
... ProductImpl is not transformed at all As you can see, the EhCache classes are being loaded directly prior to ProductImpl, and ProductImpl then skips transformation. Not sure yet if this is the definitive cause, digging in more. |
Ok, Ehcache was a false positive. However, it looks like I have found the problem for ProductImpl, I assume that all of the other classes will work in a similar fashion. Here's what I did:
I lost a LOT of time debugging at this point because I was using a remote debugger. Because of that, I was starting up the server and then attaching the debugger in eclipse. I got REALLY lucky here after a couple of hours of trying different things where I got really really fast. Because I got the debugger connected really quickly once, I noticed that breakpoint fired VERY VERY early on in the startup process. It was never triggered before because the debugger was always attached too late. I then modified the server startup in Eclipse to not use a remote debugger but simply debug the running eclipse application. I then got a reliable triggering of the early breakpoint, and then started going back up through the stack frames: To summarize what Tomcat is doing here, it is essentially going through and scanning all of the jars in the lib directory inside of the web application, and then scans every single class in every jar to see if it is a Well, it turns out in the enterprise jars we have a nested inner class for public interface CatalogCacheService {
static class NullProduct extends ProductImpl {}
static final NullProduct NULL_PRODUCT = new NullProduct();
static class NullCategory extends CategoryImpl {}
static final NullCategory NULL_CATEGORY = new NullCategory();
... Tomcat comes across the We'll see what happens with the rest of the classes here, but that is absolutely the cause for |
Here are the classes that fail transformation from the log messages: [ WARN] 22:33:42 MPUM - The class org.broadleafcommerce.common.sitemap.domain.SiteMapGeneratorConfigurationImpl...
[ WARN] 22:33:51 MPUM - The class org.broadleafcommerce.core.catalog.domain.CategoryImpl
[ WARN] 22:33:53 MPUM - The class org.broadleafcommerce.core.catalog.domain.ProductImpl...
[ WARN] 22:33:56 MPUM - The class org.broadleafcommerce.core.order.domain.OrderItemImpl...
[ WARN] 22:33:59 MPUM - The class org.broadleafcommerce.cms.file.domain.StaticAssetImpl...
[ WARN] 22:34:02 MPUM - The class org.broadleafcommerce.cms.url.domain.URLHandlerImpl...
[ WARN] 22:34:04 MPUM - The class com.broadleafcommerce.enterprise.workflow.domain.change.MapStructureImpl... and their causes that are being loaded by this process. For all of these cases, it is because Tomcat loads the superclass of all of the 'caused by' classes:
I am not sure how we should fix this. I think that we need to open a support ticket with Tomcat, this feels like a bug in Tomcat to me. This implementation does not let the class transformers run properly. |
Relevant comments from Tomcat's /**
* Scan the web.xml files that apply to the web application and merge them
* using the rules defined in the spec. For the global web.xml files,
* where there is duplicate configuration, the most specific level wins. ie
* an application's web.xml takes precedence over the host level or global
* web.xml file.
*/
protected void webConfig() {
/*
* Anything and everything can override the global and host defaults.
* This is implemented in two parts
* - Handle as a web fragment that gets added after everything else so
* everything else takes priority
* - Mark Servlets as overridable so SCI configuration can replace
* configuration from the defaults
*/
/*
* The rules for annotation scanning are not as clear-cut as one might
* think. Tomcat implements the following process:
* - As per SRV.1.6.2, Tomcat will scan for annotations regardless of
* which Servlet spec version is declared in web.xml. The EG has
* confirmed this is the expected behaviour.
* - As per http://java.net/jira/browse/SERVLET_SPEC-36, if the main
* web.xml is marked as metadata-complete, JARs are still processed
* for SCIs.
* - If metadata-complete=true and an absolute ordering is specified,
* JARs excluded from the ordering are also excluded from the SCI
* processing.
* - If an SCI has a @HandlesType annotation then all classes (except
* those in JARs excluded from an absolute ordering) need to be
* scanned to check if they match.
*/
...
...
... |
I opened a Tomcat bug at https://issues.apache.org/bugzilla/show_bug.cgi?id=57274. |
As I think about this more, dunno what Tomcat can really do about this, if anything. Spring adds class transformers late in the game (after this ServletContainerInitializer scanning takes place), and we do it even later because we don't add transformers until the persistence unit starts up (after all the Spring beans have been initialized). The problem actually affects every single domain class that represents a superclass. I would imagine that Tomcat added the classloader part to parse the superclass and interfaces for a performance improvement on startup. One possible fix on their part would be to disable this performance improvement so that every single class is scanned by looking it up via a FileInputStream (and thus not do classloading for those super classes) but it is unlikely that this will change. That said, after reading through http://java.net/jira/browse/SERVLET_SPEC-36 (and viewing the commit in Tomcat that I cannot find at the moment), it looks like you can add an <absolute-ordering /> I have tested this out and I can now successfully deploy on Tomcat 8! Woohoo! This also has the added benefit of improving startup time since Tomcat doesn't have to scan all classes in all jars. Also, since that By the way, with Tomcat 8 (and I think later versions of Tomcat 7? Need to go confirm exactly which versions) there is no need at all to specify the This whole process is somewhat concerning though as it has brought to light some fundamental problems with class transformation. I am not sure what the answer is here other than to be mindful of these potential issues. I also have a few logging changes that I will push up to distinguish between ERROR states that will cause really bad problems (within the classes above) and misconfigurations, then I think this issue can be closed. |
… transforming and throw an exception if we detect that a class could not be transformed
The changes that I made are to:
I am committing this change to both 3.1 and 3.2. Even though we just released 3.1.9-GA, I do not think it is necessary to release a high-priority 3.1.10-GA patch release as this can be quickly resolved within individual users' applications (by adding Also, I went back through today and verified my changes with JRebel. Both JRebel 6.0.0 and JRebel 6.0.1 do not work with Tomcat 8 and our class transformers. There are actually a TON of entity classes that do not get transformed by our transformers (way more than the original set above). Unfortunately since JRebel is closed source, I cannot go and debug their obfuscated code for class loading 👎. -1 points for closed source proprietary code. I did use JRebel 6 on Tomcat 7 and had no problems with class transformation there. I have opened an issue with JRebel located at http://zeroturnaround.com/forums/topic/tomcat-8-and-spring-class-transformation/. I am going to keep this issue open until hearing back from JRebel. |
@phillipuniverse I had some problems with JRebel over the weekend (Gradle, Jrebel, Tomcat and IntelliJ what a mess, I think my site will be done by 2020 at this rate :/) and hit the forums and noticed the issue you were having. Probably not the answer you're looking for but, take a look at http://zeroturnaround.com/software/jrebel/learn/jrebel-plugins/ |
…etContainerInitializers according to the Servlet 3.0 spec
@RapidTransit thanks for the suggestion. I don't think the plugin architecture doesn't actually make sense in this case. JRebel already triggers a reload of the Hibernate session on changing a domain class. Because the sessions reloads, it reloads the Also, one of the Jrebel devs replied to my form post and said they have a fix to using |
@phillipuniverse just a last resort in case of a can't fix/won't fix |
Per the JRebel issue that I linked, as of the JRebel Dec-05, 2014 @ 14:37 UTC 6.0.2-SNAPSHOT this has been fully resolved. For those following this thread, our official Tomcat 8 support with JRebel will only be for 6.0.2 and above. |
One final note here. Session persistence in Tomcat should always be disabled. We currently store full instances of the following classes in session:
If you use Tomcat's session persistence, then when Tomcat starts up it will load all of the session data, thus triggering a class load of these classes before the persistence manager. This can be disabled in <Context>
<!-- disable session persistence -->
<Manager pathname="" />
</Context> Re-opening to provide more logging around disabling session persistence. |
Sadly this issue must be resurrected, as the fix that I proposed (using For completeness sake, there is also a way to prevent jars from being scanned by this process with the property Since not using a |
This has been proven to happen on both Tomcat 8 and Tomcat 7.0.53. When turning on TRACE level debugging, some classes are detected as not having been transformed even though they should be.
From @ktisdell, this was the output on Tomcat 7.0.53:
For me, I had some of the same (like
MultiTenantAdminUserImpl
) but also some different ones (likeProductImpl
):First of all, if I am not mistaken this represents a very serious error state so I think that the debug logging needs to change to the ERROR level (and not TRACE).
I have also determined it is definitely later versions of Tomcat by trying these permutations:
Other references from Spring issues that have been opened regarding changes to Tomcat's class loader: https://jira.spring.io/browse/SPR-11447 and https://jira.spring.io/browse/SPR-11446.
As we have now confirmed that this affects later versions of Tomcat 7 (not just Tomcat 8) then I think this is a very critical issue.
The text was updated successfully, but these errors were encountered: