search

Moocar / logback-gelf

Logback plugin to send GELF messages to graylog2 server
Apache License 2.0
147 stars 59 forks source link

Unexpected IO failure #53

Closed maricn closed 9 years ago

maricn commented 9 years ago

We had just experienced this error on projects using 0.2beta2 version, and not on projects communicating with same gl2 server with 0.1x versions of gelf appender. After this error, logs were no longer sent to gl2 server (though connection was just fine).

08:23:54,482 |-ERROR in me.moocar.logbackgelf.GelfUDPAppender[graylogComm] - IO failure in appender java.net.PortUnreachableException: ICMP Port Unreachable
    at java.net.PortUnreachableException: ICMP Port Unreachable
    at  at java.net.PlainDatagramSocketImpl.send(Native Method)
    at  at java.net.DatagramSocket.send(Unknown Source)
    at  at me.moocar.logbackgelf.GelfChunkingOutputStream.sendBytes(GelfChunkingOutputStream.java:175)
    at  at me.moocar.logbackgelf.GelfChunkingOutputStream.flush(GelfChunkingOutputStream.java:149)
    at  at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:137)
    at  at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
    at  at me.moocar.logbackgelf.GelfUDPAppender.writeOut(GelfUDPAppender.java:96)
    at  at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
    at  at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
    at  at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
    at  at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at  at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
    at  at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
    at  at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
    at  at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at  at ch.qos.logback.classic.Logger.info(Logger.java:600)
    at  at ...
Moocar commented 9 years ago

Interesting. a PortUnreachableException means that a ping was sent to the remote host but didn't get through. Which implies one of the following:

  1. The port is wrong. Though this can't be the case if it was working before
  2. Firewalls are playing with the network
  3. Some kind of network partition.

I'm guessing it's 2 or 3. But if that's true, the issue is that the Socket never reconnects. I'll do a little playing to see if I can reproduce it.

Moocar commented 9 years ago

I ran ip tables to simulate a rejected UDP port and reproduced the issue. Once an error has occurred, the flush() function throws an IOException which essentially crashes the Appender. I'll add in some restart functionality into the mix. Thanks for trying out 0.2 and submitting the report!

maricn commented 9 years ago

Glad to be able to help. Looking forward for the fix.

Moocar commented 9 years ago

Fixed in PR #54

Moocar commented 9 years ago

I just released beta3 with this fix. Should be up on maven central in 2 hours.

andreasfranz commented 8 years ago

Hi, somehow we still experience that problem in our system. We use version 0.2 and after a deployment to a sailfin server with a cluster reboot we didn't get any log messages in graylog. After a cluster restart they appear again. The stack trace looks quite simial to the one from @maricn :

[#|2015-12-10T15:02:39.812+0100|INFO|sun-glassfish-comms-server2.0|javax.enterprise.system.stream.out|_ThreadID=11;_ThreadName=pool-1-thread-1;|15:02:39,805 |-ERROR in me.moocar.logbackgelf.GelfUDPAppender[caiServerAppender] - IO Exception in UDP output stream java.net.PortUnreachableException: ICMP Port Unreachable
    at java.net.PortUnreachableException: ICMP Port Unreachable
    at  at java.net.PlainDatagramSocketImpl.send(Native Method)
    at  at java.net.DatagramSocket.send(DatagramSocket.java:625)
    at  at me.moocar.logbackgelf.GelfChunkingOutputStream.sendBytes(GelfChunkingOutputStream.java:175)
    at  at me.moocar.logbackgelf.GelfChunkingOutputStream.flush(GelfChunkingOutputStream.java:149)
    at  at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:137)
    at  at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
    at  at me.moocar.logbackgelf.GelfUDPAppender.writeOut(GelfUDPAppender.java:97)
    at  at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
    at  at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
    at  at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
    at  at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at  at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
    at  at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
    at  at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
    at  at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at  at ch.qos.logback.classic.Logger.log(Logger.java:788)
    at  at org.apache.commons.logging.impl.SLF4JLocationAwareLog.info(SLF4JLocationAwareLog.java:155)
    at  at org.dozer.util.InitLogger.log(InitLogger.java:45)
    at  at org.dozer.config.GlobalSettings.loadGlobalSettings(GlobalSettings.java:115)
    at  at org.dozer.config.GlobalSettings.<init>(GlobalSettings.java:68)
    at  at org.dozer.config.GlobalSettings.<clinit>(GlobalSettings.java:48)
    at  at org.dozer.stats.StatisticsManagerImpl.<init>(StatisticsManagerImpl.java:40)
    at  at org.dozer.stats.GlobalStatistics.<init>(GlobalStatistics.java:29)
    at  at org.dozer.stats.GlobalStatistics.<clinit>(GlobalStatistics.java:24)
    at  at org.dozer.DozerBeanMapper.<clinit>(DozerBeanMapper.java:53)
    at  at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at  at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
    at  at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
    at  at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
    at  at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:147)
    at  at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:76)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:990)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:943)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:485)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
    at  at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
    at  at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:322)
    at  at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:106)
    at  at org.springframework.beans.factory.support.ConstructorResolver.resolveConstructorArguments(ConstructorResolver.java:630)
    at  at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:148)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1035)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:939)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:485)
    at  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
    at  at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
    at  at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
    at  at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:609)
    at  at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
    at  at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:469)
    at  at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:383)
    at  at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:283)
    at  at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:111)
    at  at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4655)
    at  at org.apache.catalina.core.StandardContext.start(StandardContext.java:5364)
    at  at com.sun.enterprise.web.WebModule.start(WebModule.java:345)
    at  at com.ericsson.ssa.config.ConvergedContextImpl.start(ConvergedContextImpl.java:144)
    at  at com.sun.enterprise.web.LifecycleStarter.doRun(LifecycleStarter.java:58)
    at  at com.sun.appserv.management.util.misc.RunnableBase.runSync(RunnableBase.java:304)
    at  at com.sun.appserv.management.util.misc.RunnableBase._submit(RunnableBase.java:176)
    at  at com.sun.appserv.management.util.misc.RunnableBase.submit(RunnableBase.java:192)
    at  at com.sun.enterprise.web.VirtualServer.startChildren(VirtualServer.java:1762)
    at  at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1244)
    at  at org.apache.catalina.core.StandardHost.start(StandardHost.java:971)
    at  at com.sun.enterprise.web.LifecycleStarter.doRun(LifecycleStarter.java:58)
    at  at com.sun.appserv.management.util.misc.RunnableBase.runSync(RunnableBase.java:304)
    at  at com.sun.appserv.management.util.misc.RunnableBase.run(RunnableBase.java:341)
    at  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
    at  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
    at  at java.util.concurrent.FutureTask.run(FutureTask.java:138)
    at  at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at  at java.lang.Thread.run(Thread.java:662)
|#]