log4j2 (2.0.1) Async Appender errorRef usage

Question

We use log4j2 for message logging in our applications. Currently, our log4j2 configurations use an Async Appender which then reference a Socket Appender (protocol="tcp") to write logs to a remote Logstash Server:

<Socket name="logstash" host="logging" port="4560" protocol="tcp" >
      <LogStashJSONLayout>

        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />

        <KeyValuePair key="tomcat.host" value="${env:HOSTNAME}"/>
        <KeyValuePair key="tomcat.port" value="${env:CONNECTOR_PORT}"/>
        <KeyValuePair key="tomcat.service" value="${web:contextPath}"/>
      </LogStashJSONLayout>       
    </Socket>

    <Async name="async">
        <AppenderRef ref="logstash"/>
    </Async>

What we would now like to do is to, modify our log4j2 configuration to include a fallback RollingFile Appender for cases where the Logstash Server is not available and, to accomplish this, we are thinking that we would modify the Async Appender by:

Setting 'blocking=false'.
Setting 'ignoreExceptions="false"'
Setting an 'errorRef' to point to our fallback RollingFile Appender.

Is this a sensible way of accomplishing this? And, if so, how would the Async Appender's XML look like? We tried the following:

    <RollingFile name="fallbackFile"
        fileName="${sys:catalina.base}/logs/${web:contextPath}-fallback.log" 
        filePattern="${sys:catalina.base}/logs/${web:contextPath}-%d{dd-MMM-yyyy}-%i.log"
        append="true">
        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        <Policies>
            <SizeBasedTriggeringPolicy size="1 GB" />
        </Policies>
    </RollingFile>

    <Socket name="logstash" host="logging" port="4560" protocol="tcp" >
      <LogStashJSONLayout>
        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        <KeyValuePair key="tomcat.host" value="${env:HOSTNAME}"/>
        <KeyValuePair key="tomcat.port" value="${env:CONNECTOR_PORT}"/>
        <KeyValuePair key="tomcat.service" value="${web:contextPath}"/>
      </LogStashJSONLayout>       
    </Socket>       

    <Async name="async" blocking="false" ignoreExceptions="false" errorRef="fallbackFile">
        <AppenderRef ref="logstash"/>           
    </Async>

But we get an error when deploying the application in an environment where the Logstash Server node is purposely unavailable:

2015-04-24 09:55:43,688 ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.SocketAppender for element Socket. 2015-04-24 09:55:43,702 ERROR Null object returned for Socket in Appenders. 2015-04-24 09:55:43,707 ERROR No appender named logstash was configured Apr 24, 2015 9:55:43 AM org.apache.catalina.core.StandardContext startInternal SEVERE: Error during ServletContainerInitializer processing javax.servlet.ServletException: Failed to instantiate WebApplicationInitializer class at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:160) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5481) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649) at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1081) at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:553) at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1668) at sun.reflect.GeneratedMethodAccessor532.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:301) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source) at org.apache.catalina.manager.ManagerServlet.check(ManagerServlet.java:1480) at org.apache.catalina.manager.ManagerServlet.deploy(ManagerServlet.java:709) at org.apache.catalina.manager.ManagerServlet.doPut(ManagerServlet.java:450) at javax.servlet.http.HttpServlet.service(HttpServlet.java:649) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:612) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Unknown Source) Caused by: java.lang.ExceptionInInitializerError at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) at java.lang.reflect.Constructor.newInstance(Unknown Source) at java.lang.Class.newInstance(Unknown Source) at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:157) ... 42 more Caused by: java.lang.NullPointerException at org.apache.logging.log4j.core.appender.AsyncAppender.start(AsyncAppender.java:108) at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:157) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:364) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:422) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:146) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:75) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:37) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:468) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:403) at com.company.service.config.WebInitialiser.(WebInitialiser.java:21)

What are we doing wrong? Should we be using a Failover Appender instead maybe?

--------- UPDATE ---------

After further testing, I can say that the above setup works in cases where the Socket Appender's host is available but NOT the port (e.g. service unavailable). But it does NOT work in cases where the Socket Appender's host is NOT available (e.g. unknown host).

Now, in order to have the fallbackFile Appender work in both cases (service unavailable and unknown host), I have included a Failover Appender over our SocketAppender:

    <RollingFile name="fallbackFile"
        fileName="${sys:catalina.base}/logs/${web:contextPath}-fallback.log" 
        filePattern="${sys:catalina.base}/logs/${web:contextPath}-%d{dd-MMM-yyyy}-%i.log"
        append="true">
        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        <Policies>
            <SizeBasedTriggeringPolicy size="1 GB" />
        </Policies>
    </RollingFile>

    <Socket name="logstash" host="logging" port="4560" protocol="tcp" >
      <LogStashJSONLayout>
        <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        <KeyValuePair key="tomcat.host" value="${env:HOSTNAME}"/>
        <KeyValuePair key="tomcat.port" value="${env:CONNECTOR_PORT}"/>
        <KeyValuePair key="tomcat.service" value="${web:contextPath}"/>
      </LogStashJSONLayout>       
    </Socket>       

    <Failover name="failover" primary="logstash">
        <Failovers>
            <AppenderRef ref="fallbackFile"/>
        </Failovers>
    </Failover>

    <Async name="async" bufferSize="10" blocking="false" ignoreExceptions="false" errorRef="fallbackFile">
        <AppenderRef ref="failover"/>
    </Async>

This configuration seems to be giving us the behaviour we wanted.

Any cleaner/neater solutions or even comments on this configuration would be most welcome.

Cheers, PM

mp911de mp911de · Accepted Answer · 2015-04-28T10:27:00

logstash-gelf is much more resilient than log4j2's SocketAppender. AsyncAppenders can protect applications up to a certain degree, still you can run into issues with TCP, such as service not available, slow or the connection/reconnection eats up time.

GELF works over UDP, so if the service is down/not reachable, it does not affect your application performance in any way. The only thing that might happen is that you might lose log events, but you've got the file fallback for that case.

A full example of logstash-gelf's config looks like:

<Configuration>
    <Appenders>
        <Gelf name="gelf" host="udp:localhost" port="12201" version="1.1" extractStackTrace="true"
              filterStackTrace="true" mdcProfiling="true" includeFullMdc="true" maximumMessageSize="8192"
              originHost="%host{fqdn}">
            <Field name="timestamp" pattern="%d{dd MMM yyyy HH:mm:ss,SSS}" />
            <Field name="level" pattern="%level" />
            <Field name="simpleClassName" pattern="%C{1}" />
            <Field name="className" pattern="%C" />
            <Field name="server" pattern="%host" />
            <Field name="server.fqdn" pattern="%host{fqdn}" />

            <!-- This is a static field -->
            <Field name="fieldName2" literal="fieldValue2" />

            <!-- This is a field using MDC -->
            <Field name="mdcField2" mdc="mdcField2" /> 
            <DynamicMdcFields regex="mdc.*" />
            <DynamicMdcFields regex="(mdc|MDC)fields" />
        </Gelf>
    </Appenders>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="gelf" />
        </Root>
    </Loggers>
</Configuration>

Full documentation is available here: http://logging.paluch.biz/

log4j2 (2.0.1) Async Appender errorRef usage

2 Answers