Logging cơ bản — SLF4J facade, Logback, log level và hierarchy

TL;DR: Boot logging stack gồm 4 layer — SLF4J facade (API duy nhất code app dùng), Logback implementation, bridge libs redirect log từ JUL/Log4j legacy, và output. Facade pattern tồn tại để đổi implementation không sửa code: swap Logback sang Log4j2 là đổi 2 dòng pom, không chạm business code. 5 log level từ TRACE đến ERROR tạo thành hierarchy theo package — set com.example: DEBUG bật toàn bộ package đó, child override parent bằng config cụ thể hơn. Tại sao dùng log.info("{}", x) thay log.info("val=" + x): placeholder lazy — nếu level INFO tắt, string concat không bao giờ chạy.

Mỗi app Boot in log từ giây đầu — không cần config. Đó là vì Boot đã pre-wire toàn bộ logging stack qua spring-boot-starter-logging. Bài này bóc cơ chế đó: 4 layer trong stack là gì, façade pattern giải quyết vấn đề gì, log level + hierarchy hoạt động ra sao, và cấu hình qua property.

Bài trước — Profile groups & patterns — giải thích cách Boot chọn config theo môi trường. Bài này nối tiếp: logging cũng cấu hình theo môi trường, và hiểu stack là nền để Structured logging ở bài sau thêm JSON output cho production.

1. Stack logging Boot — 4 layer

Boot không tự code logger. Nó tích hợp sẵn 4 component thành một stack:

flowchart TB
    App["App code<br/>(OrderService, Controller...)"]
    SLF4J["SLF4J<br/>Simple Logging Facade for Java<br/>(API thuan tuy)"]
    Logback["Logback<br/>(implementation default)"]
    Output["Console / File / Cloud"]
    Bridges["Bridge libs<br/>jul-to-slf4j (java.util.logging)<br/>log4j-to-slf4j (Log4j 1.x)<br/>jcl-over-slf4j (commons-logging)"]
    ThirdParty["Thu vien 3rd-party<br/>(Hibernate, Tomcat, Jackson...)"]

    App -->|"log.info(...)"| SLF4J
    SLF4J -->|"binding"| Logback
    Logback --> Output
    ThirdParty --> Bridges
    Bridges --> SLF4J

Ba layer đầu:

• SLF4J (Simple Logging Facade for Java): interface thuần tuý — Logger, LoggerFactory. Code app chỉ dùng SLF4J, không import Logback trực tiếp.
• Logback: implementation mặc định Boot chọn. Nhận log từ SLF4J, format, ghi ra console/file.
• Bridge libs: capture log từ thư viện cũ (Tomcat dùng java.util.logging, Hibernate dùng Log4j 1.x, Spring cũ dùng Commons Logging) rồi redirect qua SLF4J. Nhờ đó toàn bộ log từ mọi thư viện đều unified qua Logback.

spring-boot-starter-logging (transitive của mọi spring-boot-starter-*) pull cả 4 layer:

spring-boot-starter-logging
├── logback-classic        (implementation)
├── logback-core
├── slf4j-api              (facade API)
├── jul-to-slf4j           (bridge JUL)
├── log4j-to-slf4j         (bridge Log4j)
└── jcl-over-slf4j         (bridge Commons Logging)

Không cần khai báo gì — add bất kỳ starter nào thì logging stack sẵn sàng.

2. Tại sao cần facade — vấn đề không có SLF4J

Trước SLF4J ra đời (2004), mỗi thư viện Java dùng logging framework riêng: Hibernate dùng Log4j, Spring dùng Commons Logging, Tomcat dùng JUL. App muốn log phải chọn 1 trong số đó — và nếu đổi framework log, phải sửa mọi import trong codebase.

SLF4J giải quyết bằng facade pattern (hay còn gọi abstraction layer): code viết theo interface chung của SLF4J, implementation thật (Logback, Log4j2...) chỉ khai báo ở pom/gradle, không xuất hiện trong source.

flowchart LR
    Code["App code<br/>import org.slf4j.Logger"]
    API["SLF4J API<br/>(interface)"]
    LB["Logback<br/>(binding A)"]
    L4J["Log4j2<br/>(binding B)"]

    Code --> API
    API -.->|"runtime binding"| LB
    API -.->|"swap pom.xml"| L4J

Hệ quả thực tế: đổi từ Logback sang Log4j2 chỉ cần:

1. Exclude spring-boot-starter-logging trong pom.
2. Add spring-boot-starter-log4j2.

Không một dòng business code nào thay đổi — vì tất cả đều import org.slf4j.Logger, không phải ch.qos.logback.Logger hay org.apache.log4j.Logger.

3. Dùng SLF4J đúng cách

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Service
public class OrderService {
    private static final Logger log = LoggerFactory.getLogger(OrderService.class);

    public void place(Order order) {
        log.debug("Placing order {}", order.id());
        log.info("Order placed: id={}, total={}", order.id(), order.total());

        try {
            payment.charge(order);
        } catch (PaymentException e) {
            log.error("Payment failed for order {}", order.id(), e);  // exception la param cuoi
        }
    }
}

Hoặc dùng Lombok @Slf4j để tự generate dòng khai báo logger:

@Slf4j   // generate: private static final Logger log = LoggerFactory.getLogger(OrderService.class);
@Service
public class OrderService {
    public void place(Order order) {
        log.info("Order placed: id={}", order.id());
    }
}

3.1 Tại sao placeholder {} thay vì string concat

Đây là lý do cơ chế, không chỉ style:

// SAI: string concat chay ngay ca khi DEBUG tat
log.debug("Processing order " + order.id() + " for user " + order.userId());

// DUNG: placeholder lazy — chi substitute khi DEBUG bat
log.debug("Processing order {} for user {}", order.id(), order.userId());

Khi level là INFO (DEBUG tắt), dòng thứ nhất vẫn tạo string trung gian rồi bỏ đi — lãng phí CPU cho mỗi call trong hot path. Dòng thứ hai: SLF4J kiểm tra level trước, nếu DEBUG không bật thì không gọi toString() trên các arguments, không tạo string nào cả.

Trong loop xử lý nghìn record/giây, sự khác biệt này có thể đo được.

3.2 Exception phải là param cuối

// SAI: chi in message, MAT stack trace
log.error("Payment failed: " + e.getMessage());
log.error("Payment failed: {}", e.getMessage());

// DUNG: SLF4J detect param cuoi la Throwable, log ca stack trace
log.error("Payment failed for order {}", order.id(), e);

SLF4J có xử lý đặc biệt: nếu param cuối cùng là Throwable, nó log toàn bộ stack trace. Khi debug bug production, stack trace là thông tin không thể thay thế — dùng hai cách sai trên sẽ chỉ thấy một dòng message, không biết lỗi từ đâu.

4. Năm log level và hierarchy theo package

4.1 Năm level

SLF4J định nghĩa 5 level theo thứ tự từ chi tiết nhất đến quan trọng nhất:

Quy tắc: khi level được set là INFO, chỉ INFO/WARN/ERROR đi qua. TRACE và DEBUG bị chặn trước khi format.

4.2 Hierarchy theo package

Logger có hierarchy tự động theo tên package — child inherit level từ parent gần nhất có config:

# application.yml
logging:
  level:
    root: WARN                              # default cho tat ca logger
    com.example: INFO                       # moi class trong com.example
    com.example.payment: DEBUG              # override — payment DEBUG
    com.example.payment.StripeGateway: INFO # override lai — class cu the INFO
    org.hibernate.SQL: DEBUG                # log SQL query
    org.springframework.web: WARN           # giam noise Spring web

Cách resolve level cho com.example.payment.StripeGateway:

1. Tìm config cho com.example.payment.StripeGateway → có, INFO. Apply.

Cách resolve cho com.example.payment.PaypalGateway:

1. Tìm com.example.payment.PaypalGateway → không có.
2. Walk up: com.example.payment → có, DEBUG. Apply.

flowchart TB
    Root["root: WARN"]
    Pkg["com.example: INFO"]
    Pay["com.example.payment: DEBUG"]
    Stripe["com.example.payment.StripeGateway: INFO<br/>(explicit override)"]
    Paypal["com.example.payment.PaypalGateway<br/>(no config, inherit DEBUG)"]
    Order["com.example.order.OrderService<br/>(no config, inherit INFO)"]

    Root --> Pkg
    Pkg --> Pay
    Pkg --> Order
    Pay --> Stripe
    Pay --> Paypal

4.3 Cấu hình qua logging.level.*

logging:
  level:
    root: INFO
    com.example: DEBUG
    com.example.security: INFO           # tiet che hon — security class log it hon
    org.hibernate.SQL: DEBUG
    org.hibernate.orm.jdbc.bind: TRACE   # log SQL parameter

Không cần logback-spring.xml cho việc này — property đủ cho 90% case điều chỉnh level.

5. Cơ chế bên dưới — vì sao log level check nhanh

Khi bạn gọi log.debug("..."), Logback không lập tức format và ghi — nó kiểm tra level trước:

flowchart TB
    Call["log.debug(msg, args...)"]
    Check{"Logger.isDebugEnabled()?<br/>(compare integer level)"}
    Skip["return ngay, khong lam gi"]
    Fmt["format message<br/>(substitute placeholder)"]
    Append["appender: ghi Console/File"]

    Call --> Check
    Check -->|"No (level > DEBUG)"| Skip
    Check -->|"Yes"| Fmt
    Fmt --> Append

Level được lưu dưới dạng integer (TRACE=0, DEBUG=10, INFO=20, WARN=30, ERROR=40). Kiểm tra level là so sánh integer — O(1), gần như không có overhead. Đây là lý do placeholder lazy an toàn: nếu level check fail, SLF4J không gọi bất kỳ .toString() nào trên arguments.

Logger hierarchy cũng được cache sau lần resolve đầu tiên — không phải walk up tree mỗi lần log.

6. Pitfall phổ biến

❌ Nhầm 1 — String concat trong log call:

log.debug("user " + userId + " action " + action);     // concat luon, ngay ca khi DEBUG tat

✅ Placeholder lazy:

log.debug("user {} action {}", userId, action);

❌ Nhầm 2 — Log exception thiếu stack trace:

log.error("Payment failed: " + e.getMessage());     // mat stack trace
log.error("Payment failed: {}", e);                 // toString() cua exception, van mat stack trace

✅ Exception là param cuối:

log.error("Payment failed for order {}", order.id(), e);   // log + full stack trace

❌ Nhầm 3 — Tưởng log.info(...) có overhead khi level INFO:

Có lẽ bạn nghĩ: "INFO là level mặc định, nên log.info(...) chắc tốn kém?" Không — INFO call có overhead gần bằng 0 khi level INFO bật, chỉ format + write. Overhead cần lo là log.debug(...) trong hot path khi level INFO (vì tốn chi phí kiểm tra + placeholder không chạy nhưng args vẫn được đánh giá nếu dùng concat).

❌ Nhầm 4 — Logger không static final:

private Logger log = LoggerFactory.getLogger(OrderService.class);  // SAI — tao moi moi instance

✅ Logger là stateless, dùng chung an toàn giữa các instance:

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

LoggerFactory.getLogger() cache logger theo tên — static final đảm bảo chỉ lookup một lần per class.

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

• Profile groups & patterns: config logging hay thay đổi theo profile — logging.level.com.example: DEBUG ở profile dev, WARN ở profile prod. Hiểu profile trước giúp tổ chức logging.level.* config hợp lý.
• Structured logging: bài tiếp theo đi sâu vào JSON log cho production (Boot 3.4 ECS format), MDC correlation ID, và dynamic log level qua Actuator. Cơ chế 4-layer stack + hierarchy bài này là nền để hiểu structured logging build trên đó.
• Externalized configuration: logging.level.* là một trong hàng trăm property Boot expose qua application.yml. Bài đó giải thích cơ chế @ConfigurationProperties và thứ tự ưu tiên nguồn config — quan trọng khi override logging.level qua environment variable trong K8s.

Tóm tắt

• Boot pre-wire 4-layer logging stack qua spring-boot-starter-logging: SLF4J facade → Logback impl → bridge libs (JUL/Log4j/Commons Logging) → output.
• Facade pattern (SLF4J): code chỉ import org.slf4j.Logger — đổi implementation không sửa business code.
• Dùng SLF4J đúng: static final logger, placeholder {} thay concat (lazy — chỉ substitute khi level bật), exception là param cuối (log.error("msg", e) để có stack trace).
• 5 level TRACE/DEBUG/INFO/WARN/ERROR. Production default: INFO+. DEBUG tắt khi deploy — dùng cho diagnostics tạm thời.
• Hierarchy theo package: logger child inherit level từ parent gần nhất có config. Set com.example: INFO làm baseline; override package/class cụ thể.
• Cấu hình qua logging.level.* property — không cần logback-spring.xml cho 90% case điều chỉnh level.

Tự kiểm tra

Bài tiếp theo: Structured logging (Boot 3.4) + production