[
https://issues.apache.org/jira/browse/LOG4J2-1311?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16109279#comment-16109279
]
Dustin Koupal commented on LOG4J2-1311:
---------------------------------------
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.
> SocketAppender will lose several events after re-connection to server
> ---------------------------------------------------------------------
>
> Key: LOG4J2-1311
> URL: https://issues.apache.org/jira/browse/LOG4J2-1311
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.5
> Environment: OS: Ubuntu 14.04 LTS
> Reporter: Xibing Liang
> Fix For: 2.9
>
>
> -------> 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):
> {code}
> 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
> {code}
> -------> 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:
> {code}
> 三月 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
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
