So they are being kicked off by the webapp initialization. That follows what I was thinking. I have a suspicion I may have to put in some code to check if the logging classes are in the same ClassLoader as the current ClassLoader. If they aren’t we probably need to kick off logging initialization there first and then continue with the current initialization. I need to look at the code again and try a few things though.
Is it possible you could create a Jira for this and attach a sample project that demonstrates the problem? Another workaround to this is to not use the ClassLoaderContextSelector. If you really want a common configuration across all your web apps then you can use the BasicContextSelector. However, that may cause problems if you try to use hot deployment. Ralph > On Aug 19, 2016, at 1:52 PM, Bill Okara <billok...@gmail.com> wrote: > > Hi Gary, > > actually the full stack was attached in that email already, please let > me know if you can't find them... > (Attachments: stacktrace_webinf.txt (5 kb) stacktrace_tomcatlib.txt (7 kb) ) > > Yeah, that's kinda my understanding (or guess) too. That is, by > putting the log related jars in tomcat/lib, when the initializing the > log4j2.xml, it's trying to initialize the KafkaAppender, whose jars > are in tomcat/lib, thus it's trying to initialize the log4j config for > that context. > > I was able to hack/workaround the issue by adding a log4j2-test.xml in > WEB-INF/classes, and not using the KafkaAppender in the > log4j2-test.xml. In that case, when initializing for tomcat/lib, the > log4j2-test.xml got picked up before the log4j2.xml, and that kinda > avoided the problem. > > But the caveat is that no longer can use KafkaAppender for anything > logged by jars in tomcat/lib... > > I guess KafkaAppender is a special case that it's using a jar that > also uses SLF4j/log4j logs. > > By having the jars in tomcat/lib seems like pretty clean for webapps > to share same logging implementation and use their specific config. > but not sure how to better workaround / resolve the issue without > limiting all jars in tomcat/lib to not using KafkaAppender in this > case. > > comments? > > > Thanks! > Bill > > > On Fri, Aug 19, 2016 at 1:07 PM, Ralph Goers <ralph.go...@dslextreme.com > <mailto:ralph.go...@dslextreme.com>> wrote: >> I have a suspicion the key part of the stack trace isn’t included. I am >> guessing that the code that causes the first call to the Kafka appender is >> in your web app. This causes the ClassLoaderContextSelector to initialize >> Log4j for the web app ClassLoader. Kafka itself is in tomcat/lib. When it >> logs it causes Log4j to initialize for the tomcat/lib ClassLoader. That is >> why you see the second LoggerContext start. >> >> However, I would really like to see the stack frames just below where you >> stopped to see what is causing the initial Log4j initialization. >> >> Ralph >> >> >> >>> On Aug 19, 2016, at 11:17 AM, Bill Okara <billok...@gmail.com >>> <mailto:billok...@gmail.com>> wrote: >>> >>> thanks for guiding me through this, Gary! >>> >>> Attached are 2 stack dumps, one is with the log related jars packaged >>> in WEB-INF/lib, the other is having the jars provided in tomcat/lib, >>> and below are what I noticed; that is, >>> in WEB-INF/lib case, when initializing the >>> private static final Logger log = >>> LoggerFactory.getLogger(KafkaProducer.class); >>> >>> the getLogger seemed returned a logger right the way, vs in tomcat/lib >>> case, it's trying to go through the getContext etc init stack, which >>> in turn hit the KafkaProducer.java:188 again and had the NULL log at >>> that case... >>> >>> comments? >>> >>> In WEB-INF/lib: >>> at org.apache.kafka.common.config.ConfigDef.define(ConfigDef.java:346) >>> at >>> org.apache.kafka.clients.producer.ProducerConfig.<clinit>(ProducerConfig.java:220) >>> at >>> org.apache.kafka.clients.producer.KafkaProducer.<init>(KafkaProducer.java:188) >>> at >>> org.apache.logging.log4j.core.appender.mom.kafka.DefaultKafkaProducerFactory.newKafkaProducer(DefaultKafkaProducerFactory.java:29) >>> >>> In tomcat/lib: >>> at >>> org.apache.kafka.clients.producer.ProducerConfig.<clinit>(ProducerConfig.java:220) >>> at >>> org.apache.kafka.clients.producer.KafkaProducer.<init>(KafkaProducer.java:188) >>> at >>> org.apache.logging.log4j.core.appender.mom.kafka.DefaultKafkaProducerFactory.newKafkaProducer(DefaultKafkaProducerFactory.java:29) >>> at >>> org.apache.logging.log4j.core.appender.mom.kafka.KafkaManager.startup(KafkaManager.java:86) >>> at >>> org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.start(KafkaAppender.java:96) >>> at >>> org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:247) >>> at >>> org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:496) >>> at >>> org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:566) >>> at >>> org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:582) >>> at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:217) >>> at >>> org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:152) >>> at >>> org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) >>> at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194) >>> at >>> org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:103) >>> at >>> org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43) >>> at >>> org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42) >>> at >>> org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29) >>> at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358) >>> at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:383) >>> at >>> org.apache.kafka.clients.producer.KafkaProducer.<clinit>(KafkaProducer.java:131) >>> at >>> org.apache.logging.log4j.core.appender.mom.kafka.DefaultKafkaProducerFactory.newKafkaProducer(DefaultKafkaProducerFactory.java:29) >>> >>> >>> >>> Thanks, >>> Bill >>> >>> >>> On Fri, Aug 19, 2016 at 1:46 AM, Gary Gregory <garydgreg...@gmail.com >>> <mailto:garydgreg...@gmail.com> <mailto:garydgreg...@gmail.com >>> <mailto:garydgreg...@gmail.com>>> wrote: >>>> Hello Bill, >>>> >>>> What you could do is start the whole thing in a debugger and put a >>>> breakpoint >>>> in >>>> org.apache.kafka.clients.producer.KafkaProducer.KafkaProducer(ProducerConfig, >>>> Serializer<K>, Serializer<V>) here: >>>> >>>> } catch (Throwable t) { >>>> // call close methods if internal objects are already >>>> constructed >>>> // this is to prevent resource leak. see KAFKA-2121 >>>> ---> BREAKPOINT close(0, TimeUnit.MILLISECONDS, true); >>>> // now propagate the exception >>>> throw new KafkaException("Failed to construct kafka producer", >>>> t); >>>> } >>>> >>>> This line 333 in the latest client. >>>> >>>> Then you can dump the exception on the console and tell us what it is >>>> because we are not seeing it in the log since the close method causes its >>>> own NPE. >>>> >>>> Finding what the Throwable is will be a lot. >>>> >>>> Gary >>>> >>>> On Thu, Aug 18, 2016 at 11:30 PM, Bill Okara <billok...@gmail.com >>>> <mailto:billok...@gmail.com> <mailto:billok...@gmail.com >>>> <mailto:billok...@gmail.com>>> wrote: >>>> >>>>> Thanks, Gary, >>>>> >>>>> you're probably right, the log in log.info <http://log.info/> >>>>> <http://log.info/ <http://log.info/>> seems to be the culprit. >>>>> >>>>> By doing the 'trace' in log4j2.xml, it seems that the initialization >>>>> for the WebappClassLoader actually finished OK, but when initializing >>>>> for the Parent Classloader, it's when the NullPointerException >>>>> happened. Any idea why? or did the config in the previously attached >>>>> src look legit? >>>>> >>>>> Thanks! >>>>> Bill >>>>> >>>>> ------- >>>>> 2016-08-19 00:00:28,569 localhost-startStop-1 DEBUG Configuration >>>>> XmlConfiguration[location=jndi:/localhost/log4j-appender/WEB-INF/classes/ >>>>> log4j2.xml] >>>>> initialized >>>>> 2016-08-19 00:00:28,570 localhost-startStop-1 DEBUG Starting >>>>> configuration XmlConfiguration[location=jndi:/localhost/log4j- >>>>> appender/WEB-INF/classes/log4j2.xml] >>>>> 2016-08-19 00:00:28,579 localhost-startStop-1 DEBUG PluginManager >>>>> 'Converter' found 41 plugins >>>>> 2016-08-19 00:00:28,579 localhost-startStop-1 DEBUG Starting >>>>> OutputStreamManager SYSTEM_OUT.false.false-3 >>>>> 2016-08-19 00:00:28,579 localhost-startStop-1 DEBUG Starting >>>>> LoggerContext[name=1f32e575, >>>>> org.apache.logging.log4j.core.LoggerContext@28b2955f]... >>>>> 2016-08-19 00:00:28,580 localhost-startStop-1 DEBUG Reconfiguration >>>>> started for context[name=1f32e575] at URI null >>>>> (org.apache.logging.log4j.core.LoggerContext@28b2955f) with optional >>>>> ClassLoader: null >>>>> 2016-08-19 00:00:28,580 localhost-startStop-1 DEBUG Using >>>>> configurationFactory >>>>> org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@42223c17 >>>>> 2016-08-19 00:00:28,580 localhost-startStop-1 TRACE Trying to find >>>>> [log4j2-test1f32e575.properties] using context class loader >>>>> WebappClassLoader >>>>> context: /log4j-appender >>>>> delegate: false >>>>> repositories: >>>>> /WEB-INF/classes/ >>>>> ----------> Parent Classloader: >>>>> java.net.URLClassLoader@1f32e575 >>>>> class loader. >>>>> 2016-08-19 00:00:28,598 localhost-startStop-1 TRACE Trying to find >>>>> [log4j2.jsn] using ClassLoader.getSystemResource(). >>>>> 2016-08-19 00:00:28,599 localhost-startStop-1 TRACE Trying to find >>>>> [log4j2.xml] using context class loader WebappClassLoader >>>>> context: /log4j-appender >>>>> delegate: false >>>>> repositories: >>>>> /WEB-INF/classes/ >>>>> ----------> Parent Classloader: >>>>> java.net.URLClassLoader@1f32e575 >>>>> . >>>>> 2016-08-19 00:00:28,602 localhost-startStop-1 DEBUG Initializing >>>>> configuration XmlConfiguration[location=/opt/java/apache/apache-tomcat- >>>>> 7.0.70/webapps/log4j-appender/WEB-INF/classes/log4j2.xml] >>>>> 2016-08-19 00:00:28,603 localhost-startStop-1 DEBUG Installed script >>>>> engines >>>>> ... >>>>> 016-08-19 00:00:28,619 localhost-startStop-1 DEBUG Configuration >>>>> XmlConfiguration[location=/opt/java/apache/apache-tomcat- >>>>> 7.0.70/webapps/log4j-appender/WEB-INF/classes/log4j2.xml] >>>>> initialized >>>>> 2016-08-19 00:00:28,619 localhost-startStop-1 DEBUG Starting >>>>> configuration XmlConfiguration[location=/opt/java/apache/apache-tomcat- >>>>> 7.0.70/webapps/log4j-appender/WEB-INF/classes/log4j2.xml] >>>>> Aug 19, 2016 12:00:28 AM org.apache.catalina.core.ContainerBase >>>>> addChildInternal >>>>> SEVERE: ContainerBase.addChild: start: >>>>> org.apache.catalina.LifecycleException: Failed to start component >>>>> [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/log4j- >>>>> appender]] >>>>> at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:153) >>>>> at org.apache.catalina.core.ContainerBase.addChildInternal( >>>>> ContainerBase.java:899) >>>>> at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875) >>>>> at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652) >>>>> at org.apache.catalina.startup.HostConfig.deployDirectory( >>>>> HostConfig.java:1260) >>>>> at org.apache.catalina.startup.HostConfig$DeployDirectory. >>>>> run(HostConfig.java:2002) >>>>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) >>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:266) >>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker( >>>>> ThreadPoolExecutor.java:1142) >>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run( >>>>> ThreadPoolExecutor.java:617) >>>>> at java.lang.Thread.run(Thread.java:745) >>>>> Caused by: java.lang.ExceptionInInitializerError >>>>> at org.apache.logging.log4j.core.appender.mom.kafka. >>>>> DefaultKafkaProducerFactory.newKafkaProducer(DefaultKafkaProducerFactory. >>>>> java:29) >>>>> at org.apache.logging.log4j.core.appender.mom.kafka.KafkaManager.startup( >>>>> KafkaManager.java:86) >>>>> at org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.start( >>>>> KafkaAppender.java:96) >>>>> at org.apache.logging.log4j.core.config.AbstractConfiguration. >>>>> start(AbstractConfiguration.java:247) >>>>> at org.apache.logging.log4j.core.LoggerContext.setConfiguration( >>>>> LoggerContext.java:496) >>>>> at org.apache.logging.log4j.core.LoggerContext.start( >>>>> LoggerContext.java:249) >>>>> at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext( >>>>> Log4jContextFactory.java:239) >>>>> at org.apache.logging.log4j.core.config.Configurator. >>>>> initialize(Configurator.java:157) >>>>> at org.apache.logging.log4j.web.Log4jWebInitializerImpl.initializeNonJndi( >>>>> Log4jWebInitializerImpl.java:167) >>>>> at org.apache.logging.log4j.web.Log4jWebInitializerImpl.start( >>>>> Log4jWebInitializerImpl.java:109) >>>>> at org.apache.logging.log4j.web.Log4jServletContainerInitializ >>>>> er.onStartup(Log4jServletContainerInitializer.java:57) >>>>> at org.apache.catalina.core.StandardContext.startInternal( >>>>> StandardContext.java:5604) >>>>> at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147) >>>>> ... 10 more >>>>> Caused by: java.lang.NullPointerException >>>>> at org.apache.kafka.clients.producer.KafkaProducer.close( >>>>> KafkaProducer.java:658) >>>>> at org.apache.kafka.clients.producer.KafkaProducer.<init>( >>>>> KafkaProducer.java:333) >>>>> at org.apache.kafka.clients.producer.KafkaProducer.<init>( >>>>> KafkaProducer.java:188) >>>>> ------------- >>>>> >>>>> On Thu, Aug 18, 2016 at 5:40 PM, Gary Gregory <garydgreg...@gmail.com >>>>> <mailto:garydgreg...@gmail.com> <mailto:garydgreg...@gmail.com >>>>> <mailto:garydgreg...@gmail.com>>> >>>>> wrote: >>>>>> Based on the stack trace, it looks like the Slf4j logger in KafkaProducer >>>>>> is null: >>>>>> >>>>>> log.info <http://log.info/> <http://log.info/ >>>>>> <http://log.info/>>("Closing the Kafka producer with timeoutMillis = {} >>>>> ms.", >>>>>> timeUnit.toMillis(timeout)); >>>>>> >>>>>> It does not look like timeUnit can be null, so it must be log. >>>>>> >>>>>> The root problem of course if that we have an exception thrown in the >>>>>> KafkaProducer >>>>>> ctor. >>>>>> >>>>>> Gary >>>>>> >>>>>> On Thu, Aug 18, 2016 at 3:44 PM, Bill Okara <billok...@gmail.com >>>>>> <mailto:billok...@gmail.com> <mailto:billok...@gmail.com >>>>>> <mailto:billok...@gmail.com>>> wrote: >>>>>> >>>>>>> tried again, seemed like the .out extension got filtered out by mail >>>>>>> server... >>>>>>> >>>>>>> On Thu, Aug 18, 2016 at 4:41 PM, Bill Okara <billok...@gmail.com >>>>>>> <mailto:billok...@gmail.com> <mailto:billok...@gmail.com >>>>>>> <mailto:billok...@gmail.com>>> >>>>> wrote: >>>>>>>> attach the catalina.out again, didn't seem to go through last time... >>>>>>>> >>>>>>>> >>>>>>>> On Thu, Aug 18, 2016 at 4:33 PM, Bill Okara <billok...@gmail.com >>>>>>>> <mailto:billok...@gmail.com> <mailto:billok...@gmail.com >>>>>>>> <mailto:billok...@gmail.com>>> >>>>> wrote: >>>>>>>>> Hi, >>>>>>>>> >>>>>>>>> When trying out the log4j2 Kafka appender, it works ok if all the >>>>>>>>> log4j2/kafka-client related jars are packaged in the webapp's >>>>>>>>> WEB-INF/lib, like: >>>>>>>>> >>>>>>>>>> ls WEB-INF/lib/ >>>>>>>>> jackson-core-2.8.1.jar >>>>>>>>> log4j-core-2.6.2.jar >>>>>>>>> lz4-1.3.0.jar >>>>>>>>> kafka-clients-0.10.0.1.jar >>>>>>>>> log4j-slf4j-impl-2.6.2.jar >>>>>>>>> slf4j-api-1.7.21.jar >>>>>>>>> log4j-api-2.6.2.jar >>>>>>>>> log4j-web-2.6.2.jar >>>>>>>>> snappy-java-1.1.2.6.jar >>>>>>>>> >>>>>>>>> >>>>>>>>> But if the jars are provided in tomcat/lib (for all webapps), and >>>>> each >>>>>>>>> webapp will have its own log4j2.xml (as in attached war), then when >>>>>>>>> launching the webapp, will encounter: >>>>>>>>> >>>>>>>>> ----- >>>>>>>>> Caused by: java.lang.NullPointerException >>>>>>>>> at org.apache.kafka.clients.producer.KafkaProducer.close( >>>>>>> KafkaProducer.java:658) >>>>>>>>> at org.apache.kafka.clients.producer.KafkaProducer.<init>( >>>>>>> KafkaProducer.java:333) >>>>>>>>> at org.apache.kafka.clients.producer.KafkaProducer.<init>( >>>>>>> KafkaProducer.java:188) >>>>>>>>> at org.apache.logging.log4j.core.appender.mom.kafka. >>>>>>> DefaultKafkaProducerFactory.newKafkaProducer( >>>>> DefaultKafkaProducerFactory. >>>>>>> java:29) >>>>>>>>> at org.apache.logging.log4j.core.appender.mom.kafka. >>>>>>> KafkaManager.startup(KafkaManager.java:86) >>>>>>>>> at org.apache.logging.log4j.core.appender.mom.kafka. >>>>>>> KafkaAppender.start(KafkaAppender.java:96) >>>>>>>>> at org.apache.logging.log4j.core. >>>>> config.AbstractConfiguration. >>>>>>> start(AbstractConfiguration.java:247) >>>>>>>>> at org.apache.logging.log4j.core.LoggerContext. >>>>>>> setConfiguration(LoggerContext.java:496) >>>>>>>>> at org.apache.logging.log4j.core.LoggerContext.reconfigure( >>>>>>> LoggerContext.java:566) >>>>>>>>> --------- >>>>>>>>> >>>>>>>>> (full stack trace as in attached catalina.out) >>>>>>>>> >>>>>>>>> >>>>>>>>> To reproduce the error, simply: >>>>>>>>> 1) build the attached webapp, and deploy the output to tomcat/webapps >>>>>>>>> 2) move the WEB-INF/lib/*.jar to tomcat/lib (make sure WEB-INF/lib is >>>>>>>>> empty after move) >>>>>>>>> 3) start tomcat >>>>>>>>> >>>>>>>>> Tested with tomcat 7.0.70 >>>>>>>>> >>>>>>>>> Anyone encounter similar problem? or is this a bug? (log4j2 or >>>>>>>>> kafka-client bug?) >>>>>>>>> >>>>>>>>> >>>>>>>>> Thanks, >>>>>>>>> Bill >>>>>>> >>>>>>> >>>>>>> --------------------------------------------------------------------- >>>>>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org >>>>>>> <mailto:log4j-user-unsubscr...@logging.apache.org> >>>>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org >>>>>>> <mailto:log4j-user-h...@logging.apache.org> >>>>>>> >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> E-Mail: garydgreg...@gmail.com <mailto:garydgreg...@gmail.com> | >>>>>> ggreg...@apache.org <mailto:ggreg...@apache.org> >>>>>> Java Persistence with Hibernate, Second Edition >>>>>> <http://www.manning.com/bauer3/ <http://www.manning.com/bauer3/>> >>>>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/ >>>>>> <http://www.manning.com/tahchiev/>> >>>>>> Spring Batch in Action <http://www.manning.com/templier/ >>>>>> <http://www.manning.com/templier/>> >>>>>> Blog: http://garygregory.wordpress.com >>>>>> <http://garygregory.wordpress.com/> >>>>>> Home: http://garygregory.com/ <http://garygregory.com/> >>>>>> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> >>>>> >>>>> --------------------------------------------------------------------- >>>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org >>>>> <mailto:log4j-user-unsubscr...@logging.apache.org> >>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org >>>>> <mailto:log4j-user-h...@logging.apache.org> >>>>> >>>>> >>>> >>>> >>>> -- >>>> E-Mail: garydgreg...@gmail.com <mailto:garydgreg...@gmail.com> | >>>> ggreg...@apache.org <mailto:ggreg...@apache.org> >>>> Java Persistence with Hibernate, Second Edition >>>> <http://www.manning.com/bauer3/ <http://www.manning.com/bauer3/>> >>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/ >>>> <http://www.manning.com/tahchiev/>> >>>> Spring Batch in Action <http://www.manning.com/templier/ >>>> <http://www.manning.com/templier/>> >>>> Blog: http://garygregory.wordpress.com <http://garygregory.wordpress.com/> >>>> Home: http://garygregory.com/ <http://garygregory.com/> >>>> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory> >>> <stacktrace_webinf.txt><stacktrace_tomcatlib.txt> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org >>> <mailto:log4j-user-unsubscr...@logging.apache.org> >>> <mailto:log4j-user-unsubscr...@logging.apache.org >>> <mailto:log4j-user-unsubscr...@logging.apache.org>> >>> For additional commands, e-mail: log4j-user-h...@logging.apache.org >>> <mailto:log4j-user-h...@logging.apache.org> >>> <mailto:log4j-user-h...@logging.apache.org >>> <mailto:log4j-user-h...@logging.apache.org>> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > <mailto:log4j-user-unsubscr...@logging.apache.org> > For additional commands, e-mail: log4j-user-h...@logging.apache.org > <mailto:log4j-user-h...@logging.apache.org>
