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> 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> 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>> 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>> wrote: >>> >>>> Thanks, Gary, >>>> >>>> you're probably right, the log in 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>> >>>> wrote: >>>>> Based on the stack trace, it looks like the Slf4j logger in KafkaProducer >>>>> is null: >>>>> >>>>> 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>> 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>> >>>> 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>> >>>> 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 >>>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org >>>>>> >>>>> >>>>> >>>>> >>>>> -- >>>>> E-Mail: garydgreg...@gmail.com | ggreg...@apache.org >>>>> Java Persistence with Hibernate, Second Edition >>>>> <http://www.manning.com/bauer3/> >>>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/> >>>>> Spring Batch in Action <http://www.manning.com/templier/> >>>>> Blog: http://garygregory.wordpress.com >>>>> Home: http://garygregory.com/ >>>>> Tweet! http://twitter.com/GaryGregory >>>> >>>> --------------------------------------------------------------------- >>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org >>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org >>>> >>>> >>> >>> >>> -- >>> E-Mail: garydgreg...@gmail.com | ggreg...@apache.org >>> Java Persistence with Hibernate, Second Edition >>> <http://www.manning.com/bauer3/> >>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/> >>> Spring Batch in Action <http://www.manning.com/templier/> >>> Blog: http://garygregory.wordpress.com >>> Home: http://garygregory.com/ >>> Tweet! 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> >> For additional commands, e-mail: log4j-user-h...@logging.apache.org >> <mailto:log4j-user-h...@logging.apache.org> --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
