Log là thứ duy nhất bạn có khi hệ thống hỏng. Bài này về cách làm cho nó dùng được.

Trace id trong mọi dòng log

<dependency>
  <groupId>io.micrometer</groupId><artifactId>micrometer-tracing-bridge-brave</artifactId>
</dependency>

management:
  tracing:
    sampling:
      probability: 1.0
logging:
  pattern:
    level: "%5p [${spring.application.name},%X{traceId:-},%X{spanId:-}]"

  INFO [demo,6a7d94fdcbd5ed0df49b7586aa139478,f49b7586aa139478] ... : day la mot dong log trong request

Mỗi dòng log giờ mang traceId và spanId. Lọc theo traceId là ra toàn bộ đường đi của một request — qua mọi lớp, và nếu bạn có nhiều dịch vụ thì qua mọi dịch vụ.

Spring Boot 3 tự truyền trace context qua RestClient, WebClient, RestTemplate và các nguồn thông điệp. Không phải làm gì thêm.

probability: 1.0 là lấy mẫu mọi request — đúng cho dev. Sản xuất tải cao thì hạ xuống 0,1 hoặc thấp hơn; nhưng nhớ rằng khi đó chín trong mười request không có trace để tra cứu.

Chỗ nó biến mất

  trong request      : INFO [demo,6a7d94fd...,f49b7586...] ... day la mot dong log
  trong luồng @Async : INFO [demo,,]                       ... bat dau viec 1 tren luong task-2

Hai dấu phẩy trống. Trace context chạy trên ThreadLocal — bài 78 sê-ri Java — nên nó không tự đi sang luồng khác.

Đây là chỗ log bị đứt đoạn đúng lúc bạn cần nhất: công việc nền hỏng, và bạn không nối được nó với request nào đã kích hoạt.

Cách chữa với Micrometer:

@Bean
Executor executorCoTrace(BeanFactory bf) {
    var e = new ThreadPoolTaskExecutor();
    e.initialize();
    return ContextExecutorService.wrap(e.getThreadPoolExecutor(),
            ContextSnapshotFactory.builder().build()::captureAll);
}

Cùng vấn đề áp dụng cho MDC, SecurityContextHolder và mọi thứ dựa trên ThreadLocal. Với luồng ảo (bài 55) thì bẫy này nhẹ đi vì mỗi tác vụ một luồng mới, nhưng việc truyền ngữ cảnh vẫn phải làm.

Log có cấu trúc

Từ Spring Boot 3.4, JSON có sẵn không cần thư viện ngoài:

logging:
  structured:
    format:
      console: ecs        # hoặc logstash, gelf

Bài 98 sê-ri Java đã đo cái giá: JSON chậm hơn 13% và tốn thêm 19% dung lượng so với văn bản. Đổi lại là truy vấn được — traceId = "6a7d94fd..." là một trường thật thay vì một biểu thức chính quy.

Với tôi đó là món hời, và nó thành bắt buộc khi có từ hai dịch vụ trở lên.

Trong container, ghi ra stdout chứ đừng ghi ra tệp. Docker và Kubernetes đã thu log từ đó; ghi tệp trong container nghĩa là tự lo xoay vòng, tự lo dung lượng, và mất log khi container bị xoá.

Chi phí của một dòng log

Bài 98 sê-ri Java đo hai triệu lần gọi log.debug với mức DEBUG đang tắt:

  nối chuỗi              :  95 ms
  tham số {}             :  37 ms
  có isDebugEnabled()    :   4 ms

Dòng giữa là chỗ đáng nhắc lại: log.debug("x = {}", tonKem()) vẫn chạy tonKem() — nó là đối số, và Java tính đối số trước khi gọi. Cách này được dạy như cách chữa mà chỉ chữa một nửa.

Quy tắc: dùng {} mặc định; thêm canh cổng khi đối số cần tính toán.

Ghi cái gì

Ghi ở ranh giới — request vào, lời gọi ra ngoài, thông điệp nhận được. Ở giữa để chỉ số lo (bài 51).

Ghi ngữ cảnh, không ghi câu văn. "khong tim thay nguoi dung" vô dụng; log.warn("khong tim thay nguoi dung id={} trong {}", id, nguon) thì gỡ được.

Ghi ngoại lệ đúng cách:

log.error("khong luu duoc don {}", maDon, e);    // e là tham số CUỐI, không có {}

Viết log.error("loi: " + e.getMessage()) là mất dấu vết ngăn xếp — thứ duy nhất cho biết lỗi đến từ đâu.

Chọn mức cho đúng. ERROR là "cần người xử lý ngay". Ghi ERROR cho thứ không cần ai làm gì là cách nhanh nhất để mọi người tắt cảnh báo. Đơn hàng không tồn tại là kết quả bình thường — DEBUG. Mất kết nối CSDL là sự cố — ERROR.

Đừng ghi bí mật. Bài 46 đã nói: log container được gom về nơi khác và giữ rất lâu.

Log ồn che mất cảnh báo thật

Đây là bài học từ chính blog này, và tôi thấy nó bị đánh giá thấp.

ddl-auto phát drop constraint if exists mỗi lần khởi động, PostgreSQL trả NOTICE "does not exist, skipping", và Hibernate ghi ở mức WARN — hàng chục dòng vô hại ở mỗi lần khởi động.

application-prod.yml của blog hạ riêng SqlExceptionHelper và WebSecurity xuống ERROR. Sau đó log khởi động bình thường không còn dòng WARN nào — nên thấy WARN là có chuyện thật.

Đó là tiêu chuẩn đáng đặt ra: log sạch lúc bình thường, để bất thường nhìn thấy được ngay.

Truy vết phân tán

Với một dịch vụ, trace id trong log là đủ. Từ hai dịch vụ trở lên, bạn cần gửi span tới một hệ thống truy vết — nếu không, request chậm 3 giây mà bạn không biết ba giây đó nằm ở dịch vụ nào.

<dependency>
  <groupId>io.opentelemetry</groupId><artifactId>opentelemetry-exporter-otlp</artifactId>
</dependency>

management:
  otlp:
    tracing:
      endpoint: http://collector:4318/v1/traces

Lựa chọn khác là Java agent của OpenTelemetry, gắn được không cần sửa mã:

java -javaagent:opentelemetry-javaagent.jar -Dotel.service.name=don-hang -jar app.jar

Nó tự chèn ngữ cảnh vào lời gọi HTTP, truy vấn JDBC và thông điệp Kafka.

Thử ba mươi giây

docker compose logs blog | tail -50 | grep -c "traceId"

Bằng 0 nghĩa là log của bạn không nối được các dòng thuộc cùng một request. Hai dòng cấu hình ở đầu bài sửa được — và đó là thay đổi rẻ nhất làm log từ "đọc được" thành "gỡ lỗi được".

Ngày mai: @Async và @Scheduled — và pool mặc định từ chối việc thứ sáu.