Thêm traceId vào mọi dòng log bằng hai dòng cấu hình — và chỗ nó lặng lẽ biến mất

Hình dung traceId như một mã vận đơn dán lên kiện hàng. Mỗi trạm kiện đi qua đều quét và đóng cùng cái mã đó, nên về sau chỉ cần tra một con số là thấy cả hành trình — nó đã qua những tay nào, dừng ở đâu lâu. Không có mã đó, log chỉ là một đống phiếu quét rời rạc, không cách nào biết phiếu nào thuộc kiện nào. Log là thứ duy nhất bạn có khi hệ thống hỏng, và 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ụ. Một con số, cả hành trình.

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. Mã vận đơn được ghi lên cái quầy bạn đang đứng, không phải lên kiện hàng; giao việc cho đồng nghiệp ở quầy khác (luồng @Async) là họ bắt đầu với tờ giấy trắng.

Đâ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.

Nếu chỉ kiểm một thứ trong ba mươi giây, xem log có nối được các dòng cùng request không:

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".

Mẫu số chung

Hai ý vượt khỏi Spring. Một: một request phải có một danh tính (mã trace/tương quan) xâu qua mọi dòng log và mọi chặng, để từ một con số dựng lại được cả hành trình — đúng cái mã vận đơn. OpenTelemetry đã chuẩn hoá điều này xuyên ngôn ngữ (nối dõi Dapper của Google, rồi Zipkin, Jaeger). Nhưng danh tính ấy sống trong một ngữ cảnh ngầm — ThreadLocal của Java, AsyncLocalStorage của Node, contextvars của Python — và ngữ cảnh ngầm thì không tự băng qua ranh giới bất đồng bộ hay ranh giới dịch vụ, nên hệ nào cũng phải chụp-rồi-khôi-phục tường minh (ContextSnapshot của Micrometer, và bạn bè của nó). Đáng chú ý: Go giải đúng bài này bằng cách bắt truyền context.Context làm tham số — biến cái lỗi mất-ngữ-cảnh-âm-thầm thành một chỗ "bạn quên truyền ctx" nhìn thấy được.

Hai: log chỉ có ích khi tín hiệu còn nhìn thấy, nghĩa là phải sạch lúc bình thường. Log ồn và ghi ERROR cho thứ không cần làm gì đều dạy người ta ngó lơ cảnh báo — đúng cái "mệt mỏi vì báo động" (alert fatigue), chuyện chú bé chăn cừu của vận hành. Sợi chỉ chung: cho mỗi request một danh tính và truyền nó có chủ đích qua từng ranh giới luồng và dịch vụ (ngữ cảnh ngầm lặng lẽ dừng ở các mép đó), và giữ đường log lúc khoẻ mạnh thật im để đúng một dòng quan trọng lúc 2 giờ sáng không bị chôn dưới nghìn dòng vô nghĩa.

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