Unexpected IO failure

[maricn]

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]

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]

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]

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

[Moocar]

Fixed in PR #54

[Moocar]

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

[andreasfranz]

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)
|#]