I have a serious problem with TomcatLoadTimerWeaver and Log4j and I don't know how to solve it.
I'm using the following:
- Tomcat 8
- Spring Framework 4.1.2
- Log4j 2.1
- SLF4J 1.7.7
- EclipseLink 2.5.2
All logging is routed to SLF4J, and I'm using Log4j 2.1 as the logging backend. Log4j is configured to take its configuration file from a non-standard location, specified in web.xml through the log4jConfiguration context-param. The Log4jServletContainerInitializer configures Log4j properly on webapp start. All works fine as soon as Spring configures a TomcatLoadTimeWeaver.
I want to use load time weaving with EclipseLink and so I added this to my application context:
<context:load-time-weaver/>
The problem is this: once Spring registers a TomcatLoadTimeWeaver by adding a transformer to Tomcat's WebappClassLoader, the first subsequent attempt to log something through SLF4J causes Log4j to be implicitly re-initialized: since my configuration file is not in the standard location (= the root of the classpath) I get the error:
No log4j2 configuration file found
From that moment on, all log calls are not handled properly (= in the way I specified in MY log4j.xml) any more and my careful configuration of SLF4J+Log4j+bridges for Commons Logging and JUL gets completely broken.
It seems like the addition of the class loader transformer is resetting something in Log4j, so that it needs to reconfigure itself: I've spent a couple of hours to try to understand better this problem, but it's not easy without a deep knowledge of Log4j internals.
Moving my log4j.xml to log4j2.xml on the classpath root is not something I can do so easily (for deployment reasons) and in any case I'm not sure that an implicit reconfiguration of Log4j not under my control would be a good thing to live with.
Maybe an early configuration of the load time weaver (before Log4j configures itself for the first time) would make the trick, but I'm not sure how to to this, since Log4j should usually be set up before Spring itself.
Any suggestion is appreciated.
Further details
Actually, the problem doesn't occur when Spring's DefaultContextLoadTimeWeaver (which carries the TomcatLoadTimeWeaver) is initialized, but rather when the LocalContainerEntityManagerFactoryBean used to set up an EntityManagerFactory with EclipseLink is initialized (i.e., when org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet() is called), because it's at that time that org.springframework.context.weaving.DefaultContextLoadTimeWeaver.addTransformer(ClassFileTransformer) is invoked by virtue of an actual creation of the native EntityManagerFactory by EclipseLink (triggered by org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory()). So, my workaround was to register a BeanPostProcessor that intercepts the initialization of the LocalContainerEntityManagerFactoryBean and forces org.apache.logging.log4j.web.Log4jWebInitializerImpl.start() to run again and hence reconfigure Log4j with my webapp settings. I ended up with a horrible hack, though, because those Log4j classes are full of default and protected methods and I had to use reflection and place my bean post processor in org.apache.logging.log4j.core package to make this work.
Smarter solutions/suggestions/alternative approaches are welcome.
The actual cause
I debugged further the whole system and found out the cause of this problem. I opened LOG4J2-903 for this. In short, Log4j uses the class loader toString() value to search for the current log context in a map. Since Tomcat's WebappClassLoader.toString() method changes when you register a transformer, Log4j is not able to retrieve the previously configured context and creates a new one as soon as EclipseLink+Spring register the load time weaver transformer... :-(
The solution to this problem is to upgrade to Log4j 2.2, which contains the fix to LOG4J2-903.