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>
