logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bill Okara <billok...@gmail.com>
Subject Re: Log4j2 Kafka appender NullPointerException when put the related jars in tomcat lib
Date Fri, 19 Aug 2016 18:17:47 GMT
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 <garydgregory@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 <billokara@gmail.com> wrote:
>
>> Thanks, Gary,
>>
>> you're probably right, the log in 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 <garydgregory@gmail.com>
>> wrote:
>> > Based on the stack trace, it looks like the Slf4j logger in KafkaProducer
>> > is null:
>> >
>> >         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 <billokara@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 <billokara@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 <billokara@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-unsubscribe@logging.apache.org
>> >> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> >>
>> >
>> >
>> >
>> > --
>> > E-Mail: garydgregory@gmail.com | ggregory@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-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@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

Mime
View raw message