sorry Ralph, the last reply was for you (didn't read the sender carefully) On Fri, Aug 19, 2016 at 2: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> > 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
