Distributed Logging (Part 3) | Async Appender and Logging | Structured Logging (JSON)

The Post Office Drop Box Analogy

Imagine walking into a local post office to mail a letter. In a traditional synchronous system, you hand the envelope to the postal clerk. You are required to stand at the counter while the clerk weighs the letter, sticks on stamps, walks to the back room, files the manifest, unlocks the sorting safe, and deposits the envelope. Only when the envelope physically lands in the delivery crate does the clerk look up and say, "You are free to go." If twenty customers arrive simultaneously, a massive line spills onto the street because every customer waits for disk storage.

In a modern asynchronous system, you walk in and drop your envelope into an indoor steel drop box. The transaction takes half a second. You return immediately to your day. A dedicated postal sorting worker comes by every few minutes, empties the drop box, and manages the heavy lifting of sorting and filing in the background.

This is the exact difference between synchronous logging and AsyncAppender. In synchronous logging, your high throughput HTTP request thread is forced to wait for physical hard drive disk writes or network socket flushes. Under heavy traffic, disk I/O bottlenecks your entire API. AsyncAppender decouples logging from request execution by writing log events into an in memory queue, allowing business threads to return immediately while background daemon threads write to disk.

This lecture covers synchronous versus asynchronous logging performance, Logback AsyncAppender configuration, queue overflow strategies, and structured logging in JSON format for enterprise log aggregators like Elasticsearch and Datadog.

---

The Performance Penalty of Synchronous Logging

In standard logging configurations, logging operations are synchronous and blocking:

[ HTTP Thread-1 ] ---> [ Business Logic ] ---> [ logger.info() ] ---> [ Disk Write (Blocks) ] ---> [ Response Sent ]

Disk input output is orders of magnitude slower than CPU operations. A disk write might take between two and ten milliseconds. If an API request executes five log statements:

5 log statements * 5 milliseconds disk I/O = 25 milliseconds wasted on logging!

Under high concurrency (e.g. 5,000 requests per second), thread pools become starved, request latency spikes, and the application collapses — not because of business computation, but because worker threads are queued waiting for disk write operations.

---

How AsyncAppender Solves the Bottleneck

AsyncAppender acts as a wrapper around an underlying appender (such as RollingFileAppender):

[ HTTP Request Thread ]
           |
      logger.info()
           |
     (Inserts event in under 1 microsecond)
           v
+-------------------------------+
|  In-Memory BlockingQueue      |  (Default capacity: 256 events)
+-------------------------------+
           |
     (Takes event in background)
           v
[ Logback Worker Daemon Thread ]
           |
   (Performs Disk I/O)
           v
[ RollingFileAppender -> Disk ]

The calling HTTP thread inserts the log event into an in memory array queue and resumes execution immediately. The background worker thread polls the queue and performs the disk write.

---

Configuring AsyncAppender in logback-spring.xml

To make a file appender asynchronous, wrap it in an AsyncAppender:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <!-- 1. The underlying synchronous rolling file appender -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/var/log/order-service/application.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/var/log/order-service/application-%d{yyyy-MM-dd}.log.gz</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{ISO8601} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- 2. The AsyncAppender wrapper -->
    <appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
        <!-- Reference to the target appender -->
        <appender-ref ref="FILE" />

        <!-- Maximum capacity of in-memory queue (default is 256) -->
        <queueSize>1024</queueSize>

        <!-- Threshold when dropping lower level logs (default 20% remaining) -->
        <discardingThreshold>20</discardingThreshold>

        <!-- When queue is full: false = block calling thread, true = drop events -->
        <neverBlock>true</neverBlock>

        <!-- Include caller data (file, line number) - false for maximum performance -->
        <includeCallerData>false</includeCallerData>

        <!-- Maximum time in ms to wait for queue flush during JVM shutdown -->
        <maxFlushTime>3000</maxFlushTime>
    </appender>

    <!-- Attach the ASYNC appender to the root logger -->
    <root level="INFO">
        <appender-ref ref="ASYNC_FILE" />
    </root>

</configuration>

Critical Tuning Parameters Explained

1. queueSize: The capacity of the in memory BlockingQueue. Default is 256. For high throughput systems, increasing to 1024 or 2048 prevents premature queue overflow during sudden traffic surges.
2. discardingThreshold: By default, when the remaining queue capacity drops below 20%, Logback silently drops TRACE, DEBUG, and INFO events, reserving remaining slots exclusively for WARN and ERROR events. Setting this to 0 prevents discarding any log events.
3. neverBlock: If the queue fills up completely:
   • neverBlock=false (default): The calling thread blocks and waits for space in the queue, falling back to synchronous performance.
   • neverBlock=true: Log events that cannot fit in the queue are dropped immediately, guaranteeing that API latency is never impacted by logging.
4. includeCallerData: Extracting class name, method name, and line numbers requires taking an expensive thread stack snapshot. Setting includeCallerData=false dramatically increases logging throughput.

---

Structured Logging: Moving from Plain Text to JSON

In enterprise environments with hundreds of microservices, logs are collected by centralized log shippers (like Fluentd, Filebeat, Logstash) and indexed in search engines (Elasticsearch, OpenSearch, Datadog, AWS CloudWatch).

The Problem with Plain Text Logs

Consider this traditional log line:

2026-09-05 14:22:10.123 [http-nio-8080-exec-4] INFO  com.example.OrderService - Order ORD-101 created for customer CUST-99 with amount 250.00

To search for orders with amounts greater than 200, the search engine must execute expensive regular expression parsing across millions of raw text lines. If an engineer alters the sentence structure, downstream parsing scripts break immediately.

The Solution: JSON Structured Logging

With structured logging, log events are serialized as machine readable JSON documents:

{
  "timestamp": "2026-09-05T14:22:10.123Z",
  "level": "INFO",
  "thread": "http-nio-8080-exec-4",
  "logger": "com.example.OrderService",
  "message": "Order created successfully",
  "orderId": "ORD-101",
  "customerId": "CUST-99",
  "amount": 250.00
}

Now, every log aggregation tool can index orderId and amount as distinct, queryable fields. You can run instant queries like amount > 200 AND customerId: CUST-99 across petabytes of logs.

---

Implementing JSON Logging with Logstash Logback Encoder

1. Add Dependency in pom.xml

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>7.4</version>
</dependency>

2. Configure JSON Encoder in logback-spring.xml

<appender name="JSON_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/var/log/order-service/application.json</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>/var/log/order-service/application-%d{yyyy-MM-dd}.json.gz</fileNamePattern>
        <maxHistory>14</maxHistory>
    </rollingPolicy>

    <!-- Use LogstashEncoder instead of standard PatternLayoutEncoder -->
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <!-- Include custom static fields identifying this service -->
        <customFields>{"service":"order-service","environment":"production"}</customFields>
    </encoder>
</appender>

<!-- Wrap JSON appender in AsyncAppender for high throughput -->
<appender name="ASYNC_JSON" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="JSON_FILE" />
    <queueSize>2048</queueSize>
    <neverBlock>true</neverBlock>
</appender>

3. Writing Structured Arguments in Java

Using net.logstash.logback.argument.StructuredArguments:

package com.example.orderservice.service;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

import static net.logstash.logback.argument.StructuredArguments.kv;

@Service
public class OrderService {

    private static final Logger log = LoggerFactory.getLogger(OrderService.class);

    public void processOrder(String orderId, String customerId, double amount) {
        // kv("key", value) adds structured fields directly into the JSON log output
        log.info("Order processed successfully",
            kv("orderId", orderId),
            kv("customerId", customerId),
            kv("amount", amount)
        );
    }
}

When this executes, Logback outputs a single JSON object containing orderId, customerId, and amount as top level key value pairs ready for immediate indexing.

---

Interview Questions & Pitfalls

Q1: What is the main performance benefit of using AsyncAppender in high volume production services?

AsyncAppender decouples application threads from slow disk or network I/O. Instead of blocking the HTTP thread while writing to disk, the thread puts the event into an in memory queue in microseconds and returns. A background worker thread handles physical I/O asynchronously, preventing I/O latency from degrading API throughput.

Q2: What is the discardingThreshold in Logback's AsyncAppender, and why does it exist?

discardingThreshold is a percentage of queue capacity (default is 20%). When remaining queue space falls below this threshold, Logback automatically drops lower priority logs (TRACE, DEBUG, and INFO) to prevent queue exhaustion, preserving remaining capacity for critical WARN and ERROR events.

Q3: What happens to in flight log events in AsyncAppender if the JVM crashes or shuts down abruptly?

If the JVM halts abruptly (such as kill -9 or a power failure), events remaining in the in memory queue are lost. During a graceful shutdown (SIGTERM), Logback flushes pending events up to maxFlushTime (default is 1000 ms). Always ensure your container orchestrator allows graceful shutdown intervals.

Q4: Why is structured JSON logging preferred over standard text logging in microservices?

Plain text logs require complex, fragile regex parsing at search time and break whenever an engineer modifies wording. Structured JSON logs serialize fields natively, allowing log aggregators (Elasticsearch, Datadog) to index data types (numbers, timestamps, IDs) directly, enabling fast, structured filtering, metric aggregation, and alerting.

Q5: Why should includeCallerData be set to false in production AsyncAppender configurations?

Extracting caller data (class name, method name, line number) requires taking an expensive JVM stack trace snapshot at log creation time. This can decrease logging throughput by up to five times. Setting includeCallerData=false avoids stack inspection, yielding maximum asynchronous logging performance.