Structured Logging — JSON log cho ELK/Loki, MDC correlation, dynamic level

TL;DR: Log text truyền thống buộc ELK phải parse Grok pattern — fragile, tốn CPU, vỡ khi format thay đổi. Structured logging in JSON sẵn sàng index: logging.structured.format.console=ecs (Boot 3.4 GA) → mỗi dòng log là JSON object với field type-safe, ELK ingest trực tiếp không Logstash parser. MDC (Mapped Diagnostic Context) đặt requestId per-thread để correlate mọi log trong cùng request — thiếu MDC, debug production là grep mù. Dynamic log level qua POST /actuator/loggers/{logger} bật DEBUG không restart: 5 phút debug vs 30 phút deploy. Bài tập trung duy nhất vào phần production-critical này — basics SLF4J/Logback level hierarchy ở bài 05 — Logging basics.

Bạn đang theo dõi bug production. App log kiểu này:

2026-04-15T10:00:00.123 INFO 12345 --- [http-nio-8080-exec-3] com.olhub.OrderService : Order placed: id=42, total=99.99
2026-04-15T10:00:00.145 ERROR 12345 --- [http-nio-8080-exec-3] com.olhub.PaymentService : Payment failed for order 42
2026-04-15T10:00:00.146 ERROR 12345 --- [http-nio-8080-exec-7] com.olhub.OrderService : Order placed: id=43, total=150.00

Câu hỏi: dòng ERROR của order 42 và dòng INFO trước nó có phải cùng một request không? Thread name giống nhau (exec-3), nhưng thread bị reuse — exec-3 lúc 10:00:00.123 có thể là request A, lúc 10:00:01.456 là request B. Không có correlation ID, bạn không biết.

Đây là vấn đề cốt lõi của unstructured logging trong distributed system: log lines mất ngữ cảnh request và không query được theo field cụ thể trong ELK/Loki.

1. Tại sao JSON thay vì text

Log text truyền thống là string tự do — con người đọc được, nhưng Elasticsearch không. Để index, cần Logstash parse Grok pattern:

%{TIMESTAMP_ISO8601:timestamp} %{LOGLEVEL:level} %{NUMBER:pid} --- \[%{DATA:thread}\] %{DATA:logger} : %{GREEDYDATA:message}

Grok pattern có 3 vấn đề với production real:

1. Fragile: thêm traceId vào pattern log → Grok pattern vỡ → log không index → Kibana mất data trong khi team đang debug incident.
2. Tốn CPU: mỗi dòng log chạy regex match. App 10,000 request/sec = 10,000+ regex/sec trên Logstash cluster.
3. Type unsafe: process.pid được extract như string — query numeric range pid > 5000 không work trừ khi thêm convert step.

JSON log giải quyết cả 3:

{
  "@timestamp": "2026-04-15T10:00:00.123Z",
  "log.level": "INFO",
  "process.pid": 12345,
  "process.thread.name": "http-nio-8080-exec-3",
  "log.logger": "com.olhub.OrderService",
  "message": "Order placed: id=42, total=99.99",
  "service.name": "order-service",
  "service.version": "1.2.3",
  "ecs.version": "8.11"
}

Filebeat đọc → parse JSON → forward Elasticsearch trực tiếp, không qua Logstash, không Grok. Field type đúng từ đầu (process.pid là number). Thêm field mới vào app → Elasticsearch auto-map field mới, không cần sửa pipeline.

flowchart LR
  subgraph Text["Text log (cu)"]
    direction TB
    A1["App in text log"] --> B1["Filebeat doc string"]
    B1 --> C1["Logstash Grok parse"]
    C1 --> D1["Elasticsearch index"]
  end

  subgraph JSON["Structured JSON (Boot 3.4)"]
    direction TB
    A2["App in JSON log"] --> B2["Filebeat parse JSON"]
    B2 --> D2["Elasticsearch index truc tiep"]
  end

Không có Logstash trung gian — ít component vỡ hơn, latency ingest thấp hơn.

2. Cấu hình Boot 3.4 — 1 dòng property

Boot 3.4 GA (tháng 11/2024) thêm structured logging built-in. Trước đó phải tự config logback-spring.xml với Logstash encoder ~30 dòng XML. Bây giờ:

# application-prod.yml
logging:
  structured:
    format:
      console: ecs        # Elastic Common Schema
      file: ecs

3 format có sẵn:

ECS là chuẩn phổ biến nhất 2026 — chọn ecs cho ELK mới. Nếu đang dùng Loki (Grafana stack), ecs hoặc custom field vẫn work vì Loki query theo label, không cần ECS strict.

Thêm static field cho mọi log line qua logging.structured.json.add:

logging:
  structured:
    format:
      console: ecs
    json:
      add:
        environment: ${ENV:dev}
        region: ${REGION:asia-east}
        service.version: ${BUILD_VERSION:unknown}

Output mỗi dòng tự include 3 field này — không cần đặt MDC manual.

# application.yml (dev default)
# khong config logging.structured -> Logback text pattern

# application-prod.yml (production)
logging:
  structured:
    format:
      console: ecs

3. MDC — correlation ID per-request

MDC (Mapped Diagnostic Context) là ThreadLocal map — mỗi thread có map riêng chứa key-value context. Logback đọc MDC và include trong mỗi log line của thread đó.

Tại sao cần MDC: trong thread pool, 1 thread xử lý nhiều request tuần tự. Không có correlation ID, không thể distinguish dòng log nào thuộc request nào. MDC inject requestId vào thread trước khi request bắt đầu → mọi log trong request đó tự có requestId.

sequenceDiagram
  participant Client
  participant Filter as CorrelationIdFilter
  participant Service as OrderService
  participant MDC as MDC (ThreadLocal)

  Client->>Filter: POST /orders (X-Request-Id: abc123)
  Filter->>MDC: MDC.put("requestId", "abc123")
  Filter->>Service: chain.doFilter(...)
  Service->>Service: log.info("Order placed") -- auto include requestId
  Service-->>Filter: response
  Filter->>MDC: MDC.clear()
  Filter-->>Client: 200 OK

Implementation filter:

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)   // chay truoc moi filter khac
public class CorrelationIdFilter implements Filter {

    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
            throws IOException, ServletException {

        HttpServletRequest httpReq = (HttpServletRequest) req;
        String requestId = httpReq.getHeader("X-Request-Id");
        if (requestId == null) {
            requestId = UUID.randomUUID().toString();
        }

        MDC.put("requestId", requestId);
        MDC.put("userId", extractUserId(httpReq));   // tu JWT claim sub
        try {
            chain.doFilter(req, res);
        } finally {
            MDC.clear();    // BẮT BUỘC trong finally -- tranh leak sang request khac
        }
    }

    private String extractUserId(HttpServletRequest req) {
        // parse Authorization header, extract sub claim
        // return "anonymous" neu chua login
        return "anonymous";
    }
}

MDC.clear() trong finally là bắt buộc — xem phần Pitfall chính bên dưới.

3.1 MDC với structured logging

Khi dùng cả MDC và structured logging Boot 3.4, MDC fields tự include trong JSON output:

{
  "@timestamp": "2026-04-15T10:00:00.123Z",
  "log.level": "INFO",
  "message": "Order placed: id=42",
  "mdc": {
    "requestId": "abc123",
    "userId": "user-42"
  }
}

Query ELK: mdc.requestId: "abc123" → trace toàn bộ request qua mọi service. Đây là distributed tracing thủ công trước khi setup Micrometer Tracing/OpenTelemetry — đủ cho hầu hết app không có hàng trăm microservice.

3.2 MDC với text log pattern

Nếu chưa dùng structured logging, thêm %X{requestId} vào pattern:

logging:
  pattern:
    console: "%d{HH:mm:ss} %-5level [%X{requestId:-no-request}] %logger{40} : %msg%n"

%X{requestId} lấy value từ MDC. :-no-request là default nếu MDC không có key đó (request ngoài HTTP context, như scheduled job).

Output:

10:00:00 INFO  [abc123] com.olhub.OrderService : Order placed: id=42
10:00:00 INFO  [abc123] com.olhub.PaymentService : Charged $99.99
10:00:01 INFO  [def456] com.olhub.OrderService : Order placed: id=43

Giờ trace được: 2 dòng đầu cùng request abc123, dòng cuối là request def456 khác.

4. Dynamic log level qua Actuator

Scenario production phổ biến: bug xuất hiện lúc 10:00, cần bật DEBUG cho 1 package để thấy chi tiết, nhưng không thể restart app (downtime, cache cold start, ongoing transaction).

Actuator /loggers endpoint cho phép thay đổi log level runtime:

# application.yml
management:
  endpoints:
    web:
      exposure:
        include: health, loggers
  server:
    port: 9090    # tach port management khoi port app

GET /actuator/loggers/com.olhub.PaymentService — xem level hiện tại:

{
  "configuredLevel": null,
  "effectiveLevel": "INFO"
}

POST /actuator/loggers/com.olhub.PaymentService — bật DEBUG:

{ "configuredLevel": "DEBUG" }

Logger ngay lập tức (không restart) bắt đầu in DEBUG cho mọi request tiếp theo. Reset về config file:

curl -X POST http://app-internal:9090/actuator/loggers/com.olhub.PaymentService \
  -H "Content-Type: application/json" \
  -d '{"configuredLevel": null}'

Gửi null nghĩa là quay về level khai báo trong application.yml, không phải tắt logger.

Quy trình debug production với MDC + Actuator:

1. User X báo lỗi lúc 10:00. Lấy requestId từ response header hoặc từ log ELK.
2. Search log: mdc.requestId: "abc123" AND @timestamp: [2026-04-15T10:00:00 TO 2026-04-15T10:01:00] → thấy flow, identify package nào cần debug.
3. POST /actuator/loggers/com.olhub.PaymentService với DEBUG.
4. Ask user X reproduce — search log với requestId mới, trace chi tiết.
5. Identify root cause → fix → POST null để reset DEBUG.

Tổng thời gian: 5-15 phút. So với restart deployment: 30 phút downtime + cache cold start + rollback risk.

5. Đổi sang Log4j2

Logback là default của Boot — đủ cho hầu hết app. Log4j2 phù hợp khi app vượt ~50,000-100,000 log event/sec (pipeline ingest, message consumer):

<!-- pom.xml: exclude Logback, add Log4j2 -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

Tạo src/main/resources/log4j2-spring.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{40} - %msg%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="com.olhub" level="DEBUG" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        <Root level="INFO">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Code app không đổi — SLF4J facade không thay đổi API. Chỉ implementation bên dưới swap.

Khi nào nên đổi:

90% project 2026 dùng Logback. Đổi Log4j2 khi đo được bottleneck rõ ràng.

6. Cơ chế bên dưới — MDC và ThreadLocal

MDC hoạt động dựa trên ThreadLocal<Map<String, String>> — mỗi thread JVM có instance map riêng, không share giữa thread.

flowchart TB
  subgraph JVM["JVM Thread Pool"]
    T1["Thread exec-1<br/>MDC: {requestId: abc}"]
    T2["Thread exec-2<br/>MDC: {requestId: def}"]
    T3["Thread exec-3<br/>MDC: {}"]
  end
  T1 --> L1["log.info() -> include requestId=abc"]
  T2 --> L2["log.info() -> include requestId=def"]
  T3 --> L3["log.info() -> no requestId"]

Logback LoggingEvent snapshot toàn bộ MDC map của thread hiện tại tại thời điểm log. Nếu thread bị reuse (thread pool), MDC của request trước vẫn còn → log request sau có requestId sai.

Hệ quả thiết kế: MDC chỉ safe trong single-thread request lifecycle. Khi dùng async (@Async, CompletableFuture, Virtual Thread), MDC không tự propagate sang thread con. Phải copy manual:

// BIEN PHAP: copy MDC sang thread con
Map<String, String> mdcCopy = MDC.getCopyOfContextMap();
CompletableFuture.runAsync(() -> {
    if (mdcCopy != null) MDC.setContextMap(mdcCopy);
    try {
        doAsyncWork();
    } finally {
        MDC.clear();
    }
});

Hoặc dùng Micrometer Tracing — propagate context tự động qua thread boundary, virtual thread, reactive stream.

Pitfall chính

Pitfall 1 — MDC leak khi thiếu finally:

// SAI -- neu chain.doFilter throw, MDC.clear() khong chay
MDC.put("requestId", requestId);
chain.doFilter(req, res);
MDC.clear();

// DUNG -- finally dam bao clear ke ca khi exception
MDC.put("requestId", requestId);
try {
    chain.doFilter(req, res);
} finally {
    MDC.clear();
}

Hậu quả: thread exec-3 xử lý request A gặp exception, MDC.clear() không chạy; request B sau đó chạy trên chính exec-3, mọi log của B mang requestId của A — correlation ID trong ELK bị corrupt.

Pitfall 2 — JSON log bật ở dev, khó đọc:

# SAI -- bat ecs o moi profile
logging:
  structured:
    format:
      console: ecs

# DUNG -- chi bat o prod profile
# application.yml: khong config
# application-prod.yml: bat ecs

Dev phải đọc JSON thuần — mất 3x thời gian đọc log so với text pattern màu sắc của Logback.

Pitfall 3 — MDC không propagate sang async thread:

// SAI -- thread con khong co requestId
@Async
public void sendNotification(Order order) {
    log.info("Sending notification for order {}", order.id());   // requestId = null
}

// DUNG -- copy MDC truoc khi sang async
public void sendNotification(Order order) {
    Map<String, String> mdcCopy = MDC.getCopyOfContextMap();
    taskExecutor.submit(() -> {
        if (mdcCopy != null) MDC.setContextMap(mdcCopy);
        try {
            log.info("Sending notification for order {}", order.id());  // requestId co
        } finally {
            MDC.clear();
        }
    });
}

Liên hệ các bài khác

• Bài 05 — Logging basics: SLF4J 4 quy tắc, log level hierarchy theo package, logback-spring.xml custom appender — nền tảng trước khi đọc bài này.
• Tổng kết module: ôn toàn bộ module 06 Config, Profiles, Logging — structured logging là điểm highlight của phần logging production.
• Trace request qua mọi tầng: lab dùng MDC correlation ID xuyên controller → service → repository — chính cơ chế MDC mà bài này biến thành JSON field cho ELK.

Tóm tắt

• Tại sao JSON log: ELK ingest trực tiếp không Grok parser, type-safe field, thêm field không vỡ pipeline. Text log cần Logstash regex — fragile, tốn CPU.
• Boot 3.4 GA: logging.structured.format.console=ecs → JSON ECS out-of-the-box. 3 format: ecs, gelf, logstash. Thêm static field qua logging.structured.json.add.
• MDC: ThreadLocal<Map> per-thread, inject requestId trước request, Logback include tự động trong mỗi log line — correlation toàn bộ request. MDC.clear() trong finally bắt buộc.
• Structured + MDC: JSON output tự include mdc object → ELK query mdc.requestId: "abc" trace full request.
• Dynamic log level: POST /actuator/loggers/{name} bật DEBUG runtime không restart. Reset bằng null. Tách management port + auth bắt buộc.
• Log4j2: chỉ đổi khi vượt ~100k event/sec. 90% case Logback đủ. Code app không đổi (SLF4J facade).
• MDC + async: không tự propagate — phải copy MDC.getCopyOfContextMap() sang thread con.

Tự kiểm tra

logging:
structured:
  format:
    console: ecs

logging:
structured:
  format:
    console: ecs
  json:
    add:
      service.name: ${spring.application.name}
      service.version: ${BUILD_VERSION:unknown}

@Async
public void sendEmail(Order order) {
  log.info("Sending email for order {}", order.id());
}

// Goi truoc khi sang async
public void triggerSendEmail(Order order) {
  Map<String, String> mdcCopy = MDC.getCopyOfContextMap();
  taskExecutor.submit(() -> {
      if (mdcCopy != null) MDC.setContextMap(mdcCopy);
      try {
          log.info("Sending email for order {}", order.id()); // co requestId
          doSendEmail(order);
      } finally {
          MDC.clear();
      }
  });
}

Bài tiếp theo: Tổng kết module