Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1311

SocketAppender will lose several events after re-connection to server

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.5
    • Fix Version/s: 2.9.0
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      OS: Ubuntu 14.04 LTS

      Description

      -------> Firstly, I'd like to describe some conditions of our environment:
      1) Our application uses SocketAppender(TCP) for audit logs and SocketAppender(UDP) for system logs and the problem occurs for the TCP case.
      2) We have two logstash servers and there is one HAProxy Server(172.16.64.236) for load balance usage between one application server(10.111.131.28) and two logstash servers(172.16.64.33 and 172.16.64.3).
      3) Haproxy Server will break the connection if the connection is idle for several minutes, e.g. 10 minutes as we set.
      4) The content of log4j2.properties(You can only focus on the TCP SocketAppender part):

      status=TRACE
      name=TestOneLogConfig
       
      property.filename=/var/log/test-one-log/test-one-log.log
       
      #filters=threshold
       
      #filter.threshold.type=ThresholdFilter
      #filter.threshold.level=debug
       
      appenders=console, rolling, syslog, auditlog
       
      appender.console.type=Console
      appender.console.name=STDOUT
      appender.console.layout.type=PatternLayout
      appender.console.layout.pattern=%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n
       
      appender.rolling.type=RollingFile
      appender.rolling.name=RollingFile
      appender.rolling.fileName=${filename}
      appender.rolling.filePattern=/var/log/test-one-log/test-one-log-%d{MM-dd-yy-HH-mm-ss}-%i.log.gz
      appender.rolling.layout.type=PatternLayout
      appender.rolling.layout.pattern=%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n
      appender.rolling.policies.type=Policies
      appender.rolling.policies.time.type=TimeBasedTriggeringPolicy
      appender.rolling.policies.time.interval=2
      appender.rolling.policies.time.modulate=true
      appender.rolling.policies.size.type=SizeBasedTriggeringPolicy
      appender.rolling.policies.size.size=100MB
      appender.rolling.strategy.type=DefaultRolloverStrategy
      appender.rolling.strategy.max=5
      
      appender.syslog.type=Socket
      appender.syslog.name=UDPSocket
      appender.syslog.layout.type=JsonLayout
      appender.syslog.layout.locationInfo=true
      appender.syslog.layout.properties=true
      appender.syslog.protocol=UDP
      appender.syslog.host=172.16.64.3
      appender.syslog.port=4562
      
      appender.auditlog.type=Socket
      appender.auditlog.name=TCPSocket
      appender.auditlog.layout.type=JsonLayout
      appender.auditlog.layout.locationInfo=true
      appender.auditlog.layout.properties=true
      appender.auditlog.protocol=TCP
      appender.auditlog.host=172.16.64.236
      appender.auditlog.port=4561
      appender.auditlog.connectTimeoutMillis=3000
      appender.auditlog.reconnectionDelayMillis=3000
      appender.auditlog.immediateFail=true
      appender.auditlog.immediateFlush=false
      appender.auditlog.ignoreExceptions=false
      
      #appender.asyncauditlog.type=Async
      #appender.asyncauditlog.name=AsyncTCPSocket
      #appender.asyncauditlog.blocking=false
      #appender.asyncauditlog.bufferSize=2048
      #appender.asyncauditlog.ignoreExceptions=false
      #appender.asyncauditlog.asyncaudit.type=AppenderRef
      #appender.asyncauditlog.asyncaudit.ref=TCPSocket
      
      loggers=auditlogger
       
      logger.auditlogger.name=auditlogger
      logger.auditlogger.level=debug
      #logger.auditlogger.additivity=false
      logger.auditlogger.appenderRefs=auditlog
      logger.auditlogger.appenderRef.auditlog.ref=TCPSocket
       
      rootLogger.level=debug
      rootLogger.appenderRefs=console, rolling, syslog
      rootLogger.appenderRef.console.ref=STDOUT
      rootLogger.appenderRef.rolling.ref=RollingFile
      rootLogger.appenderRef.syslog.ref=UDPSocket
      

      -------> Secondly, the process/steps of meeting problem:
      1) Logstash servers, HAProxy servers and our application servers are up, and the application servers send audit logs to haproxy and logstash successfully.
      2) As we didn't do any operation, there is no audit logs come into haproxy in several minutes, and haproxy break the connection between it and application server. I use "netstat -antp" to check tcp connection states and found that: from the harpoxy server's pov, there is no connection to its 4561 tcp port and from the application server's pov, the connection to haproxy's 4561 port is CLOSE_WAIT
      3) We did a operation so that application server will write one audit log. However nothing happen, SocketAppender didn't throw any exception. And I can see that previous CLOSE_WAIT connection is also gone. This audit log didn't come into haproxy and logstash at all.
      4) We did a second operation so that application server will write the second audit log. However now SocketAppender throw a exception of and our application catches it and write the system log about it. This audit log didn't come into haproxy and logstash either.
      5) We did a third operation so that application server will write the third audit log. This time SocketAppender works well and this audit log came into haproxy and logstash.

      -------> So our question is that:
      1) What's the reason of this situation, do you have any idea?
      2) Is there any solution to write the first and second audit log to log server finally? The audit log is really importance for us.

      P.S.
      Here I paste the logs of console(from eclipse), you can see there are serveral prints of "DEBUG auditlogger:57 - LXB 0.0.0.0 xClone roles successfully" after re-connection, however logstash only receive the last one:

      三月 09, 2016 4:58:01 下午 org.apache.catalina.core.AprLifecycleListener init
      信息: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
      三月 09, 2016 4:58:01 下午 org.apache.tomcat.util.digester.SetPropertiesRule begin
      警告: [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.j2ee.server:test-one-log' did not find a matching property.
      三月 09, 2016 4:58:02 下午 org.apache.coyote.AbstractProtocol init
      信息: Initializing ProtocolHandler ["http-bio-8080"]
      三月 09, 2016 4:58:02 下午 org.apache.coyote.AbstractProtocol init
      信息: Initializing ProtocolHandler ["ajp-bio-8009"]
      三月 09, 2016 4:58:02 下午 org.apache.catalina.startup.Catalina load
      信息: Initialization processed in 1050 ms
      三月 09, 2016 4:58:02 下午 org.apache.catalina.core.StandardService startInternal
      信息: Starting service Catalina
      三月 09, 2016 4:58:02 下午 org.apache.catalina.core.StandardEngine startInternal
      信息: Starting Servlet Engine: Apache Tomcat/7.0.47
      三月 09, 2016 4:58:03 下午 org.apache.catalina.loader.WebappClassLoader validateJarFile
      信息: validateJarFile(/home/xibing-liang/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp2/wtpwebapps/test-one-log/WEB-INF/lib/javax.servlet-api-3.1.0.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offending class: javax/servlet/Servlet.class
      三月 09, 2016 4:58:06 下午 org.apache.catalina.core.ApplicationContext log
      信息: No Spring WebApplicationInitializer types detected on classpath
      SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
      SLF4J: Defaulting to no-operation (NOP) logger implementation
      SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
      三月 09, 2016 4:58:06 下午 org.apache.catalina.core.ApplicationContext log
      信息: Initializing Spring root WebApplicationContext
      三月 09, 2016 4:58:07 下午 org.apache.catalina.core.ApplicationContext log
      信息: Initializing Spring FrameworkServlet 'mvc-dispatcher'
      2016-03-09 16:58:07,694 localhost-startStop-1 DEBUG Initializing configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@574c1328
      2016-03-09 16:58:07,705 localhost-startStop-1 DEBUG Installed script engines
      2016-03-09 16:58:07,717 localhost-startStop-1 DEBUG Mozilla Rhino Version: 1.7 release 3 PRERELEASE, Language: ECMAScript, Threading: MULTITHREADED, Compile: true, Names: {js, rhino, JavaScript, javascript, ECMAScript, ecmascript}
      2016-03-09 16:58:07,718 localhost-startStop-1 DEBUG PluginManager 'Core' found 97 plugins
      2016-03-09 16:58:07,718 localhost-startStop-1 DEBUG PluginManager 'Level' found 0 plugins
      2016-03-09 16:58:07,723 localhost-startStop-1 DEBUG No scheduled items
      2016-03-09 16:58:07,724 localhost-startStop-1 DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
      2016-03-09 16:58:07,740 localhost-startStop-1 TRACE TypeConverterRegistry initializing.
      2016-03-09 16:58:07,740 localhost-startStop-1 DEBUG PluginManager 'TypeConverter' found 23 plugins
      2016-03-09 16:58:07,749 localhost-startStop-1 DEBUG createProperty(name="filename", value="/var/log/test-one-log/test-one-log.log")
      2016-03-09 16:58:07,750 localhost-startStop-1 DEBUG Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin].
      2016-03-09 16:58:07,770 localhost-startStop-1 DEBUG configureSubstitutor(={filename=/var/log/test-one-log/test-one-log.log}, Configuration(TestOneLogConfig))
      2016-03-09 16:58:07,771 localhost-startStop-1 DEBUG PluginManager 'Lookup' found 13 plugins
      2016-03-09 16:58:07,771 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2016-03-09 16:58:07,772 localhost-startStop-1 DEBUG createAppenderRef(ref="TCPSocket", level="null", Filter=null)
      2016-03-09 16:58:07,773 localhost-startStop-1 DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig].
      2016-03-09 16:58:07,776 localhost-startStop-1 DEBUG createLogger(additivity="null", level="DEBUG", name="auditlogger", includeLocation="null", ={TCPSocket}, ={}, Configuration(TestOneLogConfig), Filter=null)
      2016-03-09 16:58:07,779 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2016-03-09 16:58:07,780 localhost-startStop-1 DEBUG createAppenderRef(ref="STDOUT", level="null", Filter=null)
      2016-03-09 16:58:07,780 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2016-03-09 16:58:07,783 localhost-startStop-1 DEBUG createAppenderRef(ref="RollingFile", level="null", Filter=null)
      2016-03-09 16:58:07,783 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2016-03-09 16:58:07,784 localhost-startStop-1 DEBUG createAppenderRef(ref="UDPSocket", level="null", Filter=null)
      2016-03-09 16:58:07,784 localhost-startStop-1 DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
      2016-03-09 16:58:07,786 localhost-startStop-1 DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="null", ={STDOUT, RollingFile, UDPSocket}, ={}, Configuration(TestOneLogConfig), Filter=null)
      2016-03-09 16:58:07,787 localhost-startStop-1 DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
      2016-03-09 16:58:07,788 localhost-startStop-1 DEBUG createLoggers(={auditlogger, root})
      2016-03-09 16:58:07,788 localhost-startStop-1 DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
      2016-03-09 16:58:07,821 localhost-startStop-1 DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n", PatternSelector=null, Configuration(TestOneLogConfig), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null")
      2016-03-09 16:58:07,822 localhost-startStop-1 DEBUG PluginManager 'Converter' found 38 plugins
      2016-03-09 16:58:07,887 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
      2016-03-09 16:58:07,895 localhost-startStop-1 INFO Log4j appears to be running in a Servlet environment, but there's no log4j-web module available. If you want better web container support, please add the log4j-web JAR to your web archive or server lib directory.
      2016-03-09 16:58:07,896 localhost-startStop-1 DEBUG PluginManager 'Converter' found 38 plugins
      2016-03-09 16:58:07,899 localhost-startStop-1 DEBUG Starting OutputStreamManager SYSTEM_OUT.false-2
      2016-03-09 16:58:07,930 localhost-startStop-1 DEBUG ConsoleAppender$Builder(PatternLayout(%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n), Filter=null, target="null", name="STDOUT", follow="null", ignoreExceptions="null")
      2016-03-09 16:58:07,938 localhost-startStop-1 DEBUG Starting OutputStreamManager SYSTEM_OUT.false
      2016-03-09 16:58:07,940 localhost-startStop-1 DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
      2016-03-09 16:58:07,942 localhost-startStop-1 DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n", PatternSelector=null, Configuration(TestOneLogConfig), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null")
      2016-03-09 16:58:07,943 localhost-startStop-1 DEBUG Building Plugin[name=TimeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy].
      2016-03-09 16:58:07,946 localhost-startStop-1 DEBUG createPolicy(interval="2", modulate="true")
      2016-03-09 16:58:07,947 localhost-startStop-1 DEBUG Building Plugin[name=SizeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy].
      2016-03-09 16:58:07,951 localhost-startStop-1 DEBUG createPolicy(size="100MB")
      2016-03-09 16:58:07,955 localhost-startStop-1 DEBUG Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy].
      2016-03-09 16:58:07,963 localhost-startStop-1 DEBUG createPolicy(={TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=2, modulate=true), SizeBasedTriggeringPolicy(size=104857600)})
      2016-03-09 16:58:07,968 localhost-startStop-1 DEBUG Building Plugin[name=DefaultRolloverStrategy, class=org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy].
      2016-03-09 16:58:07,973 localhost-startStop-1 DEBUG createStrategy(max="5", min="null", fileIndex="null", compressionLevel="null", ={}, stopCustomActionsOnError="true", Configuration(TestOneLogConfig))
      2016-03-09 16:58:07,975 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingFileAppender].
      2016-03-09 16:58:07,980 localhost-startStop-1 DEBUG createAppender(fileName="/var/log/test-one-log/test-one-log.log", filePattern="/var/log/test-one-log/test-one-log-%d{MM-dd-yy-HH-mm-ss}-%i.log.gz", append="null", name="RollingFile", bufferedIO="null", bufferSize="null", immediateFlush="null", Policies(CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=2, modulate=true), SizeBasedTriggeringPolicy(size=104857600)])), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=5)), PatternLayout(%d{yyyy-MM-dd HH:mm:ss} [%t] %p %c:%L - %m%n), Filter=null, ignoreExceptions="null", advertise="null", advertiseURI="null", Configuration(TestOneLogConfig))
      2016-03-09 16:58:07,990 localhost-startStop-1 DEBUG Starting RollingFileManager /var/log/test-one-log/test-one-log.log
      2016-03-09 16:58:07,994 localhost-startStop-1 DEBUG PluginManager 'FileConverter' found 2 plugins
      2016-03-09 16:58:07,997 localhost-startStop-1 TRACE PatternProcessor.getNextTime returning 2016/03/09-16:45:52.000, nextFileTime=2016/03/09-16:45:51.000, prevFileTime=1970/01/01-08:00:00.000, current=2016/03/09-16:58:07.997, freq=EVERY_SECOND
      2016-03-09 16:58:08,003 localhost-startStop-1 TRACE PatternProcessor.getNextTime returning 2016/03/09-16:45:52.000, nextFileTime=2016/03/09-16:45:51.000, prevFileTime=2016/03/09-16:45:51.000, current=2016/03/09-16:58:08.002, freq=EVERY_SECOND
      2016-03-09 16:58:08,003 localhost-startStop-1 DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.JsonLayout].
      2016-03-09 16:58:08,012 localhost-startStop-1 DEBUG createLayout(locationInfo="true", properties="true", complete="false", compact="false", eventEol="false", charset="UTF-8")
      2016-03-09 16:58:08,301 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.SocketAppender].
      2016-03-09 16:58:08,308 localhost-startStop-1 DEBUG createAppender(host="172.16.64.3", port="4562", protocol="UDP", SSL=null, connectTimeoutMillis="0", reconnectionDelayMillis="0", immediateFail="true", name="UDPSocket", immediateFlush="true", ignoreExceptions="true", JsonLayout(org.apache.logging.log4j.core.layout.JsonLayout@35e97fc3), Filter=null, advertise="false", Configuration(TestOneLogConfig))
      2016-03-09 16:58:08,311 localhost-startStop-1 DEBUG Starting DatagramSocketManager UDP:172.16.64.3:4562
      2016-03-09 16:58:08,312 localhost-startStop-1 DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.JsonLayout].
      2016-03-09 16:58:08,313 localhost-startStop-1 DEBUG createLayout(locationInfo="true", properties="true", complete="false", compact="false", eventEol="false", charset="UTF-8")
      2016-03-09 16:58:08,313 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.SocketAppender].
      2016-03-09 16:58:08,316 localhost-startStop-1 DEBUG createAppender(host="172.16.64.236", port="4561", protocol="TCP", SSL=null, connectTimeoutMillis="3000", reconnectionDelayMillis="3000", immediateFail="true", name="TCPSocket", immediateFlush="false", ignoreExceptions="false", JsonLayout(org.apache.logging.log4j.core.layout.JsonLayout@6ab715ca), Filter=null, advertise="false", Configuration(TestOneLogConfig))
      2016-03-09 16:58:08,322 localhost-startStop-1 DEBUG Starting TcpSocketManager TCP:172.16.64.236:4561
      2016-03-09 16:58:08,323 localhost-startStop-1 DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
      2016-03-09 16:58:08,323 localhost-startStop-1 DEBUG createAppenders(={STDOUT, RollingFile, UDPSocket, TCPSocket})
      2016-03-09 16:58:08,324 localhost-startStop-1 DEBUG Configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@574c1328 initialized
      2016-03-09 16:58:08,325 localhost-startStop-1 DEBUG Starting configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@574c1328
      2016-03-09 16:58:08,326 localhost-startStop-1 DEBUG Started configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@574c1328 OK.
      2016-03-09 16:58:08,326 localhost-startStop-1 TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@5332203...
      2016-03-09 16:58:08,327 localhost-startStop-1 TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped.
      2016-03-09 16:58:08,327 localhost-startStop-1 TRACE DefaultConfiguration stopping root LoggerConfig.
      2016-03-09 16:58:08,327 localhost-startStop-1 TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped.
      2016-03-09 16:58:08,327 localhost-startStop-1 TRACE DefaultConfiguration stopping remaining Appenders.
      2016-03-09 16:58:08,328 localhost-startStop-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false-1
      2016-03-09 16:58:08,328 localhost-startStop-1 TRACE DefaultConfiguration stopped 1 remaining Appenders.
      2016-03-09 16:58:08,328 localhost-startStop-1 TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs.
      2016-03-09 16:58:08,329 localhost-startStop-1 DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@5332203 OK
      2016-03-09 16:58:08,339 localhost-startStop-1 TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@769c48b
      2016-03-09 16:58:08,339 localhost-startStop-1 TRACE Reregistering context (1/1): '602fc7b3' org.apache.logging.log4j.core.LoggerContext@30e6857a
      2016-03-09 16:58:08,340 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3'
      2016-03-09 16:58:08,340 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=StatusLogger'
      2016-03-09 16:58:08,341 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=ContextSelector'
      2016-03-09 16:58:08,341 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=Loggers,name=*'
      2016-03-09 16:58:08,342 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=Appenders,name=*'
      2016-03-09 16:58:08,342 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=AsyncAppenders,name=*'
      2016-03-09 16:58:08,342 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=AsyncLoggerRingBuffer'
      2016-03-09 16:58:08,343 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=602fc7b3,component=Loggers,name=*,subtype=RingBuffer'
      2016-03-09 16:58:08,344 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3
      2016-03-09 16:58:08,350 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=StatusLogger
      2016-03-09 16:58:08,352 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=ContextSelector
      2016-03-09 16:58:08,354 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Loggers,name=
      2016-03-09 16:58:08,355 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Loggers,name=auditlogger
      2016-03-09 16:58:08,356 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Appenders,name=UDPSocket
      2016-03-09 16:58:08,357 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Appenders,name=RollingFile
      2016-03-09 16:58:08,357 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Appenders,name=STDOUT
      2016-03-09 16:58:08,357 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=602fc7b3,component=Appenders,name=TCPSocket
      2016-03-09 16:58:08,359 localhost-startStop-1 TRACE Using default SystemClock for timestamps.
      2016-03-09 16:58:08,360 localhost-startStop-1 TRACE Using DummyNanoClock for nanosecond timestamps.
      2016-03-09 16:58:08,370 localhost-startStop-1 DEBUG Reconfiguration complete for context[name=602fc7b3] at URI NULL_SOURCE (org.apache.logging.log4j.core.LoggerContext@30e6857a) with optional ClassLoader: null
      2016-03-09 16:58:08,370 localhost-startStop-1 DEBUG Shutdown hook enabled. Registering a new one.
      2016-03-09 16:58:08,371 localhost-startStop-1 DEBUG LoggerContext[name=602fc7b3, org.apache.logging.log4j.core.LoggerContext@30e6857a] started OK.
      三月 09, 2016 4:58:08 下午 org.hibernate.validator.internal.util.Version <clinit>
      INFO: HV000001: Hibernate Validator 5.1.3.Final
      三月 09, 2016 4:58:09 下午 org.apache.coyote.AbstractProtocol start
      信息: Starting ProtocolHandler ["http-bio-8080"]
      三月 09, 2016 4:58:09 下午 org.apache.coyote.AbstractProtocol start
      信息: Starting ProtocolHandler ["ajp-bio-8009"]
      三月 09, 2016 4:58:09 下午 org.apache.catalina.startup.Catalina start
      信息: Server startup in 7725 ms
      2016-03-09 17:00:33 [http-bio-8080-exec-5] DEBUG www.chinacloud.com.api.ProxyController:55 - roles xClone
      2016-03-09 17:00:33,022 http-bio-8080-exec-5 TRACE PatternProcessor.getNextTime returning 2016/03/09-17:00:34.000, nextFileTime=2016/03/09-17:00:33.000, prevFileTime=2016/03/09-16:45:51.000, current=2016/03/09-17:00:33.022, freq=EVERY_SECOND
      2016-03-09 17:00:33,026 http-bio-8080-exec-5 TRACE DefaultRolloverStrategy.purge() took 3.0 milliseconds
      2016-03-09 17:00:33,029 http-bio-8080-exec-5 DEBUG RollingFileManager executing synchronous FileRenameAction[/var/log/test-one-log/test-one-log.log to /var/log/test-one-log/test-one-log-03-09-16-16-45-51-1.log, renameEmptyFiles=false]
      2016-03-09 17:00:33,029 http-bio-8080-exec-5 DEBUG RollingFileManager executing async GzCompressAction[/var/log/test-one-log/test-one-log-03-09-16-16-45-51-1.log to /var/log/test-one-log/test-one-log-03-09-16-16-45-51-1.log.gz, deleteSource=true]
      2016-03-09 17:00:33 [http-bio-8080-exec-5] DEBUG auditlogger:57 - LXB 0.0.0.0 xClone roles successfully
      PHPSESSID=kuk0kaclb0ogi2b9huei4hel02; expires=Wed, 09-Mar-2016 09:30:39 GMT; Max-Age=1800; path=/; HttpOnly
      2016-03-09 17:14:03 [http-bio-8080-exec-7] DEBUG www.chinacloud.com.api.ProxyController:55 - roles xClone
      2016-03-09 17:14:03,015 http-bio-8080-exec-7 TRACE PatternProcessor.getNextTime returning 2016/03/09-17:14:04.000, nextFileTime=2016/03/09-17:14:03.000, prevFileTime=2016/03/09-17:00:33.000, current=2016/03/09-17:14:03.013, freq=EVERY_SECOND
      2016-03-09 17:14:03,017 http-bio-8080-exec-7 TRACE DefaultRolloverStrategy.purge() took 1.0 milliseconds
      2016-03-09 17:14:03,017 http-bio-8080-exec-7 DEBUG RollingFileManager executing synchronous FileRenameAction[/var/log/test-one-log/test-one-log.log to /var/log/test-one-log/test-one-log-03-09-16-17-00-33-1.log, renameEmptyFiles=false]
      2016-03-09 17:14:03,018 http-bio-8080-exec-7 DEBUG RollingFileManager executing async GzCompressAction[/var/log/test-one-log/test-one-log-03-09-16-17-00-33-1.log to /var/log/test-one-log/test-one-log-03-09-16-17-00-33-1.log.gz, deleteSource=true]
      2016-03-09 17:14:03 [http-bio-8080-exec-7] DEBUG auditlogger:57 - LXB 0.0.0.0 xClone roles successfully
      PHPSESSID=kuk0kaclb0ogi2b9huei4hel02; expires=Wed, 09-Mar-2016 09:44:08 GMT; Max-Age=1800; path=/; HttpOnly
      2016-03-09 17:14:45 [http-bio-8080-exec-9] DEBUG www.chinacloud.com.api.ProxyController:55 - roles xClone
      2016-03-09 17:14:45,034 http-bio-8080-exec-9 TRACE PatternProcessor.getNextTime returning 2016/03/09-17:14:46.000, nextFileTime=2016/03/09-17:14:45.000, prevFileTime=2016/03/09-17:14:03.000, current=2016/03/09-17:14:45.034, freq=EVERY_SECOND
      2016-03-09 17:14:45,035 http-bio-8080-exec-9 TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
      2016-03-09 17:14:45,035 http-bio-8080-exec-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/var/log/test-one-log/test-one-log.log to /var/log/test-one-log/test-one-log-03-09-16-17-14-03-1.log, renameEmptyFiles=false]
      2016-03-09 17:14:45,035 http-bio-8080-exec-9 DEBUG RollingFileManager executing async GzCompressAction[/var/log/test-one-log/test-one-log-03-09-16-17-14-03-1.log to /var/log/test-one-log/test-one-log-03-09-16-17-14-03-1.log.gz, deleteSource=true]
      2016-03-09 17:14:45,048 http-bio-8080-exec-9 ERROR Unable to write to stream TCP:172.16.64.236:4561 for appender TCPSocket
      2016-03-09 17:14:45,048 http-bio-8080-exec-9 ERROR An exception occurred processing Appender TCPSocket org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to TCP:172.16.64.236:4561
      	at org.apache.logging.log4j.core.net.TcpSocketManager.write(TcpSocketManager.java:140)
      	at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
      	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:114)
      	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
      	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
      	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:352)
      	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
      	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:147)
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1022)
      	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:980)
      	at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:239)
      	at www.chinacloud.com.api.ProxyController.post(ProxyController.java:57)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:606)
      	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
      	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137)
      	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110)
      	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:776)
      	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:705)
      	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
      	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
      	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
      	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
      	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:868)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
      	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      	at www.chinacloud.com.filter.CORSFilter.doFilter(CORSFilter.java:28)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
      	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100)
      	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
      	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041)
      	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:603)
      	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      	at java.lang.Thread.run(Thread.java:745)
      Caused by: java.net.SocketException: 断开的管道
      	at java.net.SocketOutputStream.socketWrite0(Native Method)
      	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
      	at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
      	at org.apache.logging.log4j.core.net.TcpSocketManager.write(TcpSocketManager.java:131)
      	... 55 more
      
      2016-03-09 17:14:45 [http-bio-8080-exec-9] ERROR www.chinacloud.com.api.ProxyController:61 - LXB Audit Error: Error writing to TCP:172.16.64.236:4561
      PHPSESSID=kuk0kaclb0ogi2b9huei4hel02; expires=Wed, 09-Mar-2016 09:44:51 GMT; Max-Age=1800; path=/; HttpOnly
      2016-03-09 17:14:48,095 Thread-3 DEBUG Connection to 172.16.64.236:4561 reestablished.
      2016-03-09 17:15:39 [http-bio-8080-exec-1] DEBUG www.chinacloud.com.api.ProxyController:55 - roles xClone
      2016-03-09 17:15:39,434 http-bio-8080-exec-1 TRACE PatternProcessor.getNextTime returning 2016/03/09-17:15:40.000, nextFileTime=2016/03/09-17:15:39.000, prevFileTime=2016/03/09-17:14:45.000, current=2016/03/09-17:15:39.434, freq=EVERY_SECOND
      2016-03-09 17:15:39,435 http-bio-8080-exec-1 TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
      2016-03-09 17:15:39,436 http-bio-8080-exec-1 DEBUG RollingFileManager executing synchronous FileRenameAction[/var/log/test-one-log/test-one-log.log to /var/log/test-one-log/test-one-log-03-09-16-17-14-45-1.log, renameEmptyFiles=false]
      2016-03-09 17:15:39,436 http-bio-8080-exec-1 DEBUG RollingFileManager executing async GzCompressAction[/var/log/test-one-log/test-one-log-03-09-16-17-14-45-1.log to /var/log/test-one-log/test-one-log-03-09-16-17-14-45-1.log.gz, deleteSource=true]
      2016-03-09 17:15:39 [http-bio-8080-exec-1] DEBUG auditlogger:57 - LXB 0.0.0.0 xClone roles successfully
      PHPSESSID=kuk0kaclb0ogi2b9huei4hel02; expires=Wed, 09-Mar-2016 09:45:45 GMT; Max-Age=1800; path=/; HttpOnly
      

        Issue Links

          Activity

          Hide
          girishkuks Girish added a comment -

          Is there any resolution to this, we are also facing similar issues in our application.

          Show
          girishkuks Girish added a comment - Is there any resolution to this, we are also facing similar issues in our application.
          Hide
          garydgregory Gary Gregory added a comment -

          Hi Girish,

          Can you please try the current version 2.8.2?

          Are you available to investigate or provide a patch?

          Thank you,
          Gary

          Show
          garydgregory Gary Gregory added a comment - Hi Girish, Can you please try the current version 2.8.2? Are you available to investigate or provide a patch? Thank you, Gary
          Hide
          girishkuks Girish added a comment - - edited

          Thanks Gary for suggesting. We are already using 2.7, however we will try with 2.8.2 as well.
          Can you please verify our log4j2 config file below to check are there any issues which could be creating this as I understand latest log4j2 version has introduced buffersize and all which should hold data in buffer when tcpsocket connection is invalid and should send it as soon as next active tcp socket is established.

          <?xml version="1.0" encoding="UTF-8" ?> 
          <Configuration status="trace" monitorInterval="5">
            <Appenders>
              <Socket name="socket" host="xxxxx" port="xxxxx" reconnectDelayMillis="30000" immediateFail="false" bufferedIo="true" bufferSize="204800" protocol="TCP" immediateFlush="false">
                <PatternLayout /> 
              </Socket>
              <Async name="SplunkAsync" bufferSize="204800">
                <AppenderRef ref="socket" /> 
              </Async>
            </Appenders>
            <Loggers>
              <Root level="warn">
                <AppenderRef ref="SplunkAsync" /> 
              </Root>
              <Logger name="SplunkInfoLogger" level="info" additivity="false">
                <AppenderRef ref="SplunkAsync" /> 
              </Logger>
              <Logger name="SplunkDebugLogger" level="debug" additivity="false">
                <AppenderRef ref="SplunkAsync" /> 
              </Logger>
              <Logger name="SplunkWarnLogger" level="warn" additivity="false">
                <AppenderRef ref="SplunkAsync" /> 
              </Logger>
            </Loggers>
          </Configuration>
          
          Show
          girishkuks Girish added a comment - - edited Thanks Gary for suggesting. We are already using 2.7, however we will try with 2.8.2 as well. Can you please verify our log4j2 config file below to check are there any issues which could be creating this as I understand latest log4j2 version has introduced buffersize and all which should hold data in buffer when tcpsocket connection is invalid and should send it as soon as next active tcp socket is established. <?xml version= "1.0" encoding= "UTF-8" ?> <Configuration status= "trace" monitorInterval= "5" > <Appenders> <Socket name= "socket" host= "xxxxx" port= "xxxxx" reconnectDelayMillis= "30000" immediateFail= " false " bufferedIo= " true " bufferSize= "204800" protocol= "TCP" immediateFlush= " false " > <PatternLayout /> </Socket> <Async name= "SplunkAsync" bufferSize= "204800" > <AppenderRef ref= "socket" /> </Async> </Appenders> <Loggers> <Root level= "warn" > <AppenderRef ref= "SplunkAsync" /> </Root> <Logger name= "SplunkInfoLogger" level= "info" additivity= " false " > <AppenderRef ref= "SplunkAsync" /> </Logger> <Logger name= "SplunkDebugLogger" level= "debug" additivity= " false " > <AppenderRef ref= "SplunkAsync" /> </Logger> <Logger name= "SplunkWarnLogger" level= "warn" additivity= " false " > <AppenderRef ref= "SplunkAsync" /> </Logger> </Loggers> </Configuration>
          Hide
          girishkuks Girish added a comment - - edited

          Any suggestions to above issue is appreciated !!!

          Show
          girishkuks Girish added a comment - - edited Any suggestions to above issue is appreciated !!!
          Hide
          cooper6581 Dustin Koupal added a comment -

          Hi Girish did you end up coming up with a way to solve this issue? We are running into a similar issue and not sure the best way to proceed.

          Show
          cooper6581 Dustin Koupal added a comment - Hi Girish did you end up coming up with a way to solve this issue? We are running into a similar issue and not sure the best way to proceed.
          Hide
          jvz Matt Sicker added a comment -

          Gary Gregory has been working on a proof of concept for various appenders' ability to replay log messages on failure restarts.

          Show
          jvz Matt Sicker added a comment - Gary Gregory has been working on a proof of concept for various appenders' ability to replay log messages on failure restarts.
          Hide
          cooper6581 Dustin Koupal added a comment -

          Matt Sicker That is wonderful news. Let me know if I can help with anything (tests / documentation / etc.). Thanks!

          Show
          cooper6581 Dustin Koupal added a comment - Matt Sicker That is wonderful news. Let me know if I can help with anything (tests / documentation / etc.). Thanks!
          Hide
          garydgregory Gary Gregory added a comment -

          Hello,

          This ticket is logged against version 2.5, which is quite old. Is there any chance to get you to you to update to 2.8.2 and see what the current behavior is for you? Any changes would be in the upcoming 2.9.

          Gary

          Show
          garydgregory Gary Gregory added a comment - Hello, This ticket is logged against version 2.5, which is quite old. Is there any chance to get you to you to update to 2.8.2 and see what the current behavior is for you? Any changes would be in the upcoming 2.9. Gary
          Hide
          cooper6581 Dustin Koupal added a comment -

          I'm still able to duplicate with 2.8.2. From what I can tell, this is the expected behavior. Maybe this is more of a feature request than a bug. We have a centralized syslog endpoint that could go down due to network maintenance. Ideally, I would like to be able to configure a ring buffer that could hold N log events or N bytes. If writing to the socket fails, the event would be appended to the ring buffer. When reconnect succeeds, the buffer would be flushed.

          I dumped all the things for the test to the following gist:

          https://gist.github.com/cooper6581/e8e9eb32e6e13066498d68c4a8195dd7

          Show
          cooper6581 Dustin Koupal added a comment - I'm still able to duplicate with 2.8.2. From what I can tell, this is the expected behavior. Maybe this is more of a feature request than a bug. We have a centralized syslog endpoint that could go down due to network maintenance. Ideally, I would like to be able to configure a ring buffer that could hold N log events or N bytes. If writing to the socket fails, the event would be appended to the ring buffer. When reconnect succeeds, the buffer would be flushed. I dumped all the things for the test to the following gist: https://gist.github.com/cooper6581/e8e9eb32e6e13066498d68c4a8195dd7
          Hide
          garydgregory Gary Gregory added a comment -

          I'll look over the weekend if I can update this Appender in the same manner as the JMS Appender now better handles a server going up and down.

          Show
          garydgregory Gary Gregory added a comment - I'll look over the weekend if I can update this Appender in the same manner as the JMS Appender now better handles a server going up and down.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 83b173fe46901531482f0fbe3f13bd31a3f8ddb5 in logging-log4j-tools's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j-tools.git;h=83b173f ]

          LOG4J2-1311 SocketAppender will lose several events after
          re-connection to server.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 83b173fe46901531482f0fbe3f13bd31a3f8ddb5 in logging-log4j-tools's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j-tools.git;h=83b173f ] LOG4J2-1311 SocketAppender will lose several events after re-connection to server.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit a5f3b03aa1f0ab9f301a830371544064aa5e4c3d in logging-log4j2's branch refs/heads/master from Gary Gregory
          [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a5f3b03 ]

          LOG4J2-1311 SocketAppender will lose several events after
          re-connection to server.

          Show
          jira-bot ASF subversion and git services added a comment - Commit a5f3b03aa1f0ab9f301a830371544064aa5e4c3d in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a5f3b03 ] LOG4J2-1311 SocketAppender will lose several events after re-connection to server.
          Hide
          garydgregory Gary Gregory added a comment - - edited

          In git master. Please verify and close.

          The solution I implemented is the same as in the recently reworked JMS Appender.

          When the Appender's manager detects a communication, and reconnection is enabled, the manager tries to immediately reconnect and resend. If that fails, then the reconnect thread keeps on running and an exception is thrown.

          This is different from the previous behavior which only started the reconnect thread but did not try to resend the current event being processed.

          Note that this solution does not use a cyclic buffer or LMAX ring buffer.

          Show
          garydgregory Gary Gregory added a comment - - edited In git master. Please verify and close. The solution I implemented is the same as in the recently reworked JMS Appender. When the Appender's manager detects a communication, and reconnection is enabled, the manager tries to immediately reconnect and resend. If that fails, then the reconnect thread keeps on running and an exception is thrown. This is different from the previous behavior which only started the reconnect thread but did not try to resend the current event being processed. Note that this solution does not use a cyclic buffer or LMAX ring buffer.
          Hide
          cooper6581 Dustin Koupal added a comment -

          Unfortunately it seems that a log has a chance of being lost. The outputStream can be flushed without throwing an exception even when the server on the remote end has terminated the connection (this was a surprise to me).

          After doing some research yesterday, it seems the only way to detect a remote server has terminated the connection is to get the inputStream from the socket and see if reading from it returns -1.

          Here is a gist with a really basic test program and a crude patch for firing a thread that blocks reading from the socket's inputStream: https://gist.github.com/cooper6581/55a72b8c69e8b88fe7965af75e0979f5

          When running against master, the test program would lose a single log line before getting an IOException on write / flush to trigger the reconnect.

          Show
          cooper6581 Dustin Koupal added a comment - Unfortunately it seems that a log has a chance of being lost. The outputStream can be flushed without throwing an exception even when the server on the remote end has terminated the connection (this was a surprise to me). After doing some research yesterday, it seems the only way to detect a remote server has terminated the connection is to get the inputStream from the socket and see if reading from it returns -1. Here is a gist with a really basic test program and a crude patch for firing a thread that blocks reading from the socket's inputStream: https://gist.github.com/cooper6581/55a72b8c69e8b88fe7965af75e0979f5 When running against master, the test program would lose a single log line before getting an IOException on write / flush to trigger the reconnect.

            People

            • Assignee:
              Unassigned
              Reporter:
              liangxibing@chinacloud.com.cn Xibing Liang
            • Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development