logback stacktrace (NPE) when running in devmode

[ignasi35]

While testing for the version bump to 1.4.1 I noticed the following stacktrace (See below). It doesn't block the normal usage of the application.

14:08:36,489 |-INFO in ch.qos.logback.classic.BasicConfigurator@4de8f0ed - Setting up default configuration.
14:08:37,889 |-ERROR in ch.qos.logback.core.ConsoleAppender[console] - Appender [console] failed to append. java.lang.NullPointerException
        at java.lang.NullPointerException
        at      at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)
        at      at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
        at      at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at      at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at      at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at      at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at      at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
        at      at ch.qos.logback.classic.Logger.log(Logger.java:765)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
        at      at java.util.logging.Logger.log(Logger.java:738)
        at      at java.util.logging.Logger.doLog(Logger.java:765)
        at      at java.util.logging.Logger.logp(Logger.java:931)
        at      at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:389)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
        at      at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
        at      at org.apache.kafka.common.metrics.JmxReporter.reregister(JmxReporter.java:161)
        at      at org.apache.kafka.common.metrics.JmxReporter.metricChange(JmxReporter.java:81)
        at      at org.apache.kafka.common.metrics.Metrics.registerMetric(Metrics.java:504)
        at      at org.apache.kafka.common.metrics.Sensor.add(Sensor.java:255)
        at      at org.apache.kafka.common.metrics.Sensor.add(Sensor.java:240)
        at      at org.apache.kafka.common.network.Selector$SelectorMetrics.<init>(Selector.java:754)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:142)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:156)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:160)
        at      at org.apache.kafka.clients.consumer.KafkaConsumer.<init>(KafkaConsumer.java:701)
        at      at org.apache.kafka.clients.consumer.KafkaConsumer.<init>(KafkaConsumer.java:633)
        at      at akka.kafka.ConsumerSettings.createKafkaConsumer(ConsumerSettings.scala:358)
        at      at akka.kafka.KafkaConsumerActor.preStart(KafkaConsumerActor.scala:219)
        at      at akka.actor.Actor.aroundPreStart(Actor.scala:528)
        at      at akka.actor.Actor.aroundPreStart$(Actor.scala:528)
        at      at akka.kafka.KafkaConsumerActor.aroundPreStart(KafkaConsumerActor.scala:75)
        at      at akka.actor.ActorCell.create(ActorCell.scala:654)
        at      at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:525)
        at      at akka.actor.ActorCell.systemInvoke(ActorCell.scala:547)
        at      at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:282)
        at      at akka.dispatch.Mailbox.run(Mailbox.scala:223)
        at      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at      at java.lang.Thread.run(Thread.java:748)
14:08:37,889 |-ERROR in ch.qos.logback.core.ConsoleAppender[console] - Appender [console] failed to append. java.lang.NullPointerException
        at java.lang.NullPointerException
        at      at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)
        at      at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
        at      at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at      at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at      at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at      at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at      at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
        at      at ch.qos.logback.classic.Logger.log(Logger.java:765)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
        at      at java.util.logging.Logger.log(Logger.java:738)
        at      at java.util.logging.Logger.doLog(Logger.java:765)
        at      at java.util.logging.Logger.logp(Logger.java:931)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:914)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
        at      at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
        at      at com.codahale.metrics.JmxReporter$JmxListener.registerMBean(JmxReporter.java:510)
        at      at com.codahale.metrics.JmxReporter$JmxListener.onCounterAdded(JmxReporter.java:561)
        at      at com.codahale.metrics.MetricRegistry.notifyListenerOfAddedMetric(MetricRegistry.java:456)
        at      at com.codahale.metrics.MetricRegistry.addListener(MetricRegistry.java:297)
        at      at com.codahale.metrics.JmxReporter.start(JmxReporter.java:720)
        at      at com.datastax.driver.core.Metrics.<init>(Metrics.java:104)
        at      at com.datastax.driver.core.Cluster$Manager.init(Cluster.java:1448)
        at      at com.datastax.driver.core.Cluster.init(Cluster.java:159)
        at      at com.datastax.driver.core.Cluster.connectAsync(Cluster.java:330)
        at      at com.datastax.driver.core.Cluster.connectAsync(Cluster.java:305)
        at      at akka.persistence.cassandra.ConfigSessionProvider.$anonfun$connect$1(ConfigSessionProvider.scala:48)
        at      at scala.concurrent.Future.$anonfun$flatMap$1(Future.scala:304)
        at      at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:37)
        at      at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
        at      at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
        at      at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91)
        at      at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)
        at      at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81)
        at      at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:91)
        at      at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)
        at      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at      at java.lang.Thread.run(Thread.java:748)
14:08:37,889 |-ERROR in ch.qos.logback.core.ConsoleAppender[console] - Appender [console] failed to append. java.lang.NullPointerException
        at java.lang.NullPointerException
        at      at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)
        at      at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
        at      at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at      at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at      at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at      at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at      at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
        at      at ch.qos.logback.classic.Logger.log(Logger.java:765)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
        at      at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
        at      at java.util.logging.Logger.log(Logger.java:738)
        at      at java.util.logging.Logger.doLog(Logger.java:765)
        at      at java.util.logging.Logger.logp(Logger.java:931)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterFromRepository(DefaultMBeanServerInterceptor.java:1946)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:448)
        at      at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
        at      at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:546)
        at      at org.apache.kafka.common.metrics.JmxReporter.unregister(JmxReporter.java:152)
        at      at org.apache.kafka.common.metrics.JmxReporter.reregister(JmxReporter.java:159)
        at      at org.apache.kafka.common.metrics.JmxReporter.metricChange(JmxReporter.java:81)
        at      at org.apache.kafka.common.metrics.Metrics.registerMetric(Metrics.java:504)
        at      at org.apache.kafka.common.metrics.Sensor.add(Sensor.java:255)
        at      at org.apache.kafka.common.metrics.Sensor.add(Sensor.java:240)
        at      at org.apache.kafka.common.network.Selector$SelectorMetrics.<init>(Selector.java:746)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:142)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:156)
        at      at org.apache.kafka.common.network.Selector.<init>(Selector.java:160)
        at      at org.apache.kafka.clients.consumer.KafkaConsumer.<init>(KafkaConsumer.java:701)
        at      at org.apache.kafka.clients.consumer.KafkaConsumer.<init>(KafkaConsumer.java:633)
        at      at akka.kafka.ConsumerSettings.createKafkaConsumer(ConsumerSettings.scala:358)
        at      at akka.kafka.KafkaConsumerActor.preStart(KafkaConsumerActor.scala:219)
        at      at akka.actor.Actor.aroundPreStart(Actor.scala:528)
        at      at akka.actor.Actor.aroundPreStart$(Actor.scala:528)
        at      at akka.kafka.KafkaConsumerActor.aroundPreStart(KafkaConsumerActor.scala:75)
        at      at akka.actor.ActorCell.create(ActorCell.scala:654)
        at      at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:525)
        at      at akka.actor.ActorCell.systemInvoke(ActorCell.scala:547)
        at      at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:282)
        at      at akka.dispatch.Mailbox.run(Mailbox.scala:223)
        at      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

[TimMoore]

@ignasi35 strange I don't get this. Is is reproducible for you consistently on current master?

[TimMoore]

Could this have happened to you during a reload?

https://jira.qos.ch/browse/LOGBACK-1362 suggests that it can happen if you log after an appender is closed.

[ignasi35]

Yes, I think a reload is necessary. I think I saw it consistently and the only difference compared to other times I worked on online-auction is that I was changing code exclusively on the play frontend. I don't think that's relevant but other that the other possible cause is the bump version from 1.3 to 1.4. When I noticed the thread dump it was the first time I was working on online-auctin since we upgraded to 1.4.x