Manual · Appenders · Appenders: Async and Sifting

Appenders: Async and Sifting

SiftingAppender

As its name implies, a SiftingAppender can be used to separate (or sift) logging according to a given runtime attribute. For example, SiftingAppender can separate logging events according to user sessions, so that the logs generated by different users go into distinct log files, one log file per user.

SiftingAppender achieves this feat by creating nested appenders on the fly. Nested appenders are created based on a template specified within the configuration of the SiftingAppender itself (enclosed within the <sift> element, see example below). SiftingAppender is responsible for managing the lifecycle of child appenders. For example, SiftingAppender will automatically close and remove any stale appender. A nested appender is considered stale when nothing accesses it beyond the duration specified by the timeout parameter.

When handling a logging event, SiftingAppender will select a child appender to delegate to. The selection criteria are computed at runtime by a discriminator. The user can specify the selection criteria with the help of a Discriminator. Let us now study an example.

Example

The SiftExample application logs a message stating that the application has started. It then sets the MDC key "userid" to "Alice" and logs a message. Here is the salient code:

logger.debug("Application started"); MDC.put("userid", "Alice"); logger.debug("Alice says hello");

The template for the configuration file illustrates the use of SiftingAppender.

Example: SiftingAppender configuration (logback-examples/​src/main/resources/​chapters/appenders/​sift/byUserid.xml)

<configuration>

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <!-- in the absence of the class attribute, it is assumed that the
         desired discriminator type is
         ch.qos.logback.classic.sift.MDCBasedDiscriminator -->
    <discriminator>
      <key>userid</key>
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${userid}" class="ch.qos.logback.core.FileAppender">
        <file>${userid}.log</file>
        <append>false</append>
        <layout class="ch.qos.logback.classic.PatternLayout">
          <pattern>%d [%thread] %level %mdc %logger{35} -%kvp -%msg%n</pattern>
        </layout>
      </appender>
    </sift>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

In the absence of a class attribute, it is assumed that the discriminator type is MDCBasedDiscriminator. The discriminating value is the MDC value associated with the key given by the key property. However, if that MDC value is null, then defaultValue is used as the discriminating value.

The SiftingAppender is unique in its capacity to reference and configure child appenders. In the above example, SiftingAppender will create multiple FileAppender instances, each FileAppender instance identified by the value associated with the "userid" MDC key. Whenever the "userid" MDC key is assigned a new value, a new FileAppender instance will be built from scratch. The SiftingAppender keeps track of the appenders it creates. Appenders unused for 30 minutes will be automatically closed and discarded.

Variable export It is not enough to have different appender instances; each instance must output to a distinct target resource. To allow such differentiation, within the appender template, the key passed to the discriminator, "userid" in the above example, is exported and becomes a variable. Consequently, this variable can be used to differentiate the actual resource used by a given child appender.

Running the SiftExample application with the "byUserid.xml" configuration file shown above, will result in two distinct log files, "unknown.log" and "Alice.log".

local-scoped variables As of version 1.0.12, properties defined in local scope within the configuration file will be available to nested appenders. Moreover, you can define variables or dynamically compute variables from within the the <sift> element. Combining a variable from parts defined outside and within the <sift> element is also supported.

Getting the timeout right

For certain types of applications, it may be difficult to get the timeout parameter right. If the timeout is too small, a nested appender might be removed just to be created anew a few seconds later. This phenomenon is called trashing. If the timeout is too long and appenders are created in quick succession, you might run out of resources. Similarly, setting maxAppenderCount too low might cause trashing as well.

In many case, it may be easier to pinpoint a location in your code after which a nested appender is no longer needed. If such a location exists, even approximately, log from that location using the FINALIZE_SESSION marker. Whenever SiftingAppender sees a logging event marked as FINALIZE_SESSION it will end-of-life the associated nested appender. Upon reaching its end-of-life, a nested appender will linger for a few seconds to process any late coming events (if any) and then will be closed.

import org.slf4j.Logger;
import static ch.qos.logback.classic.​ClassicConstants.​FINALIZE_SESSION_MARKER;

  void job(String jobId) {
   
    MDC.put("jobId", jobId);
    logger.info("Starting job.");

    ... do whatever the job needs to do
    
    // will cause the nested appender reach end-of-life. It will
    // linger for a few seconds.
    logger.info(FINALIZE_SESSION_MARKER, "About to end the job");

    try {
      .. perform clean up
    } catch(Exception e);  
      // This log statement will be handled by the lingering appender. 
      // No new appender will be created.
      logger.error("unexpected error while cleaning up", e);
    }
  }

AsyncAppender

AsyncAppender logs ILoggingEvents asynchronously. It acts solely as an event dispatcher and must therefore reference another appender in order to do anything useful.

Lossy by default if 80% full AsyncAppender buffers events in a BlockingQueue. A worker thread created by AsyncAppender takes events from the head of the queue, and dispatches them to the single appender attached to AsyncAppender. Note that by default, AsyncAppender will drop events of level TRACE, DEBUG and INFO if its queue is 80% full. This strategy has an amazingly favorable effect on performance at the cost of event loss.

Application stop/redeploy Upon application shutdown or redeploy, AsyncAppender must be stopped in order to stop and reclaim the worker thread and to flush the logging events from the queue. This can be achieved by stopping the LoggerContext which will close all appenders, including any AsyncAppender instances. AsyncAppender will wait for the worker thread to flush up to the timeout specified in maxFlushTime. If you find that queued events are being discarded during close of the LoggerContext, you may need to increase the time-out. Specifying a value of 0 for maxFlushTime will force the AsyncAppender to wait for all queued events to be flushed before returning from the stop method.

Post shutdown cleanup Depending on the mode of JVM shutdown, the worker thread processing the queued events can be interrupted causing events to be stranded in the queue. This generally occurs when the LoggerContext is not stopped cleanly or when the JVM terminates outside of the typical control flow. In order to avoid interrupting the worker thread under these conditions, a shutdown hook can be inserted to the JVM runtime that stops the LoggerContext properly after JVM shutdown has been initiated. A shutdown hook may also be the preferred method for cleanly shutting down Logback when other shutdown hooks attempt to log events.

Here is the list of properties admitted by AsyncAppender:

By default, event queue is configured with a maximum capacity of 256 events. If the queue is filled up, then application threads are blocked from logging new events until the worker thread has had a chance to dispatch one or more events. When the queue is no longer at its maximum capacity, application threads are able to start logging events once again. Asynchronous logging therefore becomes pseudo-synchronous when the appender is operating at or near the capacity of its event buffer. This is not necessarily a bad thing. The appender is designed to allow the application to keep on running, albeit taking slightly more time to log events until the pressure on the appenders buffer eases.

Optimally tuning the size of the appenders event queue for maximum application throughput depends upon several factors. Any or all of the following factors are likely to cause pseudo-synchronous behavior to be exhibited:

• Large numbers of application threads
• Large numbers of logging events per application call
• Large amounts of data per logging event
• High latency of child appenders

To keep things moving, increasing the size of the queue will generally help, at the expense of heap available to the application.

Lossy behavior In light of the discussion above and in order to reduce blocking, by default, when less than 20% of the queue capacity remains, AsyncAppender will drop events of level TRACE, DEBUG and INFO keeping only events of level WARN and ERROR. This strategy ensures non-blocking handling of logging events (hence excellent performance) at the cost loosing events of level TRACE, DEBUG and INFO when the queue has less than 20% capacity. Event loss can be prevented by setting the discardingThreshold property to 0 (zero).

Example: AsyncAppender configuration (logback-examples/​src/main/resources/​chapters/appenders/​conc/logback-async.​xml)

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>myapp.log</file>
    <encoder>
      <pattern>%logger{35} -%kvp -%msg%n</pattern>
    </encoder>
  </appender>

  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE" />
  </appender>

  <root level="DEBUG">
    <appender-ref ref="ASYNC" />
  </root>
    </configuration>