Hai bài trước là metric và trace — hai trụ cột. Trụ cột thứ ba là log, thứ quen thuộc nhất mà cũng bị dùng sai nhiều nhất. Hầu hết chúng ta học log kiểu fmt.Printf("xử lý đơn %d tốn %dms\n", id, ms) — đọc bằng mắt thì ổn, nhưng khi có sự cố và bạn cần truy vấn hàng triệu dòng log ("cho tôi mọi request lỗi của user 42 trong 5 phút qua"), log văn bản thuần biến thành cơn ác mộng grep với regex mong manh. Structured logging giải quyết: log thành dữ liệu có cấu trúc (JSON), mỗi trường một khoá, máy truy vấn được. Và khi gắn thêm trace_id, log nối thẳng với trace — biến ba trụ cột rời rạc thành một hệ thống. Bài này (phần 9 loạt Observability) chạy thật slog của Go để thấy khác biệt.

Vì sao văn bản thuần thất bại ở quy mô

Log văn bản trộn dữ liệu vào một chuỗi tự do:

time=... level=INFO msg="xử lý đơn hàng" user=42 amount=224436 latency_ms=36

Với một dòng, dễ đọc. Nhưng muốn hỏi "request nào chậm hơn 100ms" bạn phải viết regex bóc số sau latency_ms=, xử lý trường hợp thiếu trường, format đổi theo thời gian... và nó vỡ ngay khi ai đó đổi thông điệp log. Máy không hiểu cấu trúc; nó chỉ thấy một chuỗi ký tự.

Structured logging đảo ngược: log là một object, mỗi thông tin là một trường có tên và kiểu. Go có log/slog trong thư viện chuẩn (từ 1.21), chuyển giữa text và JSON chỉ bằng đổi handler:

// CŨ: text thuần — một chuỗi, máy khó parse
textLog := slog.New(slog.NewTextHandler(os.Stdout, nil))

// MỚI: JSON có cấu trúc — mỗi trường một khoá
jsonLog := slog.New(slog.NewJSONHandler(f, &slog.HandlerOptions{Level: slog.LevelInfo}))

// Lấy trace_id THẬT từ span context (OpenTelemetry)
_, span := tr.Start(ctx, "POST /order")
tid := span.SpanContext().TraceID().String()

// Gắn trace_id + user_id vào MỌI dòng log của request này
lg := jsonLog.With("trace_id", tid, "user_id", u)
lg.Error("thanh toán thất bại", "err", "card_declined")

Ảnh chụp đoạn mã Go nền tối structured logging với slog, textLog dùng NewTextHandler in text thuần, jsonLog dùng NewJSONHandler in JSON có cấu trúc, lấy trace_id thật từ span context OpenTelemetry SpanContext TraceID String, gắn trace_id và user_id vào mọi dòng log của request bằng With, lg Error thanh toán thất bại, bên dưới truy vấn log JSON bằng jq select level ERROR lọc lỗi, select latency_ms lớn hơn 100 lọc chậm, map amount add tổng hợp

Hình 1: slog chuyển text↔JSON chỉ bằng đổi handler. trace_id lấy thật từ span context của OpenTelemetry rồi gắn vào mọi dòng log bằng .With(...). Bên dưới là các câu jq truy vấn log JSON — lọc, tổng hợp — thứ không làm tin cậy được với text thuần.

Đo thật: jq truy vấn log, và trace_id khớp Jaeger

Mình chạy app ghi 20 dòng log JSON (mỗi dòng gắn trace_id thật từ một span gửi sang Jaeger), rồi truy vấn bằng jq:

Ảnh chụp output thật nền tối structured logging slog và jq trace_id khớp Jaeger, log text thuần một chuỗi muốn lọc phải regex mong manh time level INFO msg xử lý đơn hàng user 42 amount 224436 latency_ms 36, log JSON mỗi trường một khoá máy đọc trực tiếp level ERROR msg thanh toán thất bại trace_id c4179940 user_id 42 err card_declined, jq truy vấn 20 dòng log lọc level ERROR được 4 dòng đếm theo level 4 ERROR 16 INFO lọc latency_ms lớn hơn 100 được 5 request chậm tổng amount 10407884, nối log với trace sức mạnh thật trace_id trong log ERROR bằng c4179940 Jaeger API xác nhận trace c4179940 có thật service order-svc thấy lỗi trong log nhảy thẳng tới trace đó trong Jaeger

Hình 2: Output thật. Log text là một chuỗi phải regex mới bóc được trường; log JSON mỗi trường một khoá. jq lọc level==ERROR ra 4 dòng, latency_ms>100 ra 5 request chậm, đếm theo level (4 ERROR/16 INFO), tổng amount = 10.407.884 — tổng hợp ngay trên log. Và trace_id trong một log ERROR được Jaeger API xác nhận là trace có thật.

Đọc kết quả:

  • Lọc theo trường: jq 'select(.level=="ERROR")' ra đúng 4 dòng lỗi; select(.latency_ms > 100) ra 5 request chậm. So sánh số (> 100) chạy tin cậy vì latency_ms là số trong JSON, không phải chuỗi cần regex. Với text thuần, so sánh số sau khi grep là chuyện vỡ vặt.
  • Tổng hợp: đếm theo level (4 ERROR, 16 INFO), cộng tổng amount = 10.407.884 — bạn tính toán học ngay trên log như trên một bảng dữ liệu. Đây là điều bất khả với log văn bản.
  • Cú chốt — nối log với trace: trace_id trong một dòng log ERROR là c4179940ca1de59f…, và khi mình hỏi Jaeger API bằng chính id đó, Jaeger xác nhận trace tồn tại thật (service order-svc). Nghĩa là: trong production, khi bạn thấy một dòng log lỗi, bạn copy trace_id của nó, dán vào Jaeger, và ngay lập tức thấy toàn bộ hành trình request đó — span nào chậm, gọi gì, lỗi ở đâu. Ba trụ cột không còn rời rạc.

Đó là giá trị lớn nhất của structured logging: không chỉ log truy vấn được, mà trace_id biến log thành điểm vào của cả hệ thống quan sát.

Correlation ID: sợi chỉ xuyên suốt

trace_id ở đây đóng vai một correlation id — một định danh chung gắn vào mọi tín hiệu (log, metric exemplar, span) của cùng một request. Khi mọi dòng log của một request mang cùng trace_id, bạn jq 'select(.trace_id=="…")' để gom toàn bộ log của riêng request đó giữa hàng triệu dòng — rồi nhảy sang trace cùng id. Không có correlation id, log của các request đan xen nhau thành một mớ không gỡ được ở môi trường nhiều request đồng thời. Gắn trace_id (và các id ngữ cảnh như user_id, request_id) là việc rẻ nhất mang lại giá trị debug lớn nhất.

Đánh đổi cần cân nhắc

JSON tốn chỗ và khó đọc bằng mắt hơn. Một dòng JSON dài và nhiều ký tự thừa ({, ", :) so với text gọn. Trên terminal lúc dev, text dễ liếc hơn. Cách thực tế: dùng text (hoặc pretty JSON) ở môi trường dev, JSON ở production nơi log được máy thu thập (Loki, Elasticsearch). slog cho đổi handler theo môi trường mà không sửa chỗ gọi log — đó chính là lý do thiết kế tách handler.

Cardinality quay lại ám ở đây. Bài trước nói cardinality giết Prometheus; log thì chịu được cardinality cao hơn nhiều (đó là lý do đẩy user_id vào log thay vì metric). Nhưng không vô hạn: hệ log như Loki đánh index theo label, và nếu bạn biến mọi trường JSON thành label index thì cũng nổ. Quy tắc: index theo trường cardinality thấp (level, service), để trường cardinality cao (trace_id, user_id) trong nội dung log tìm bằng full-text/jq, không index.

Log vẫn đắt — phải có cấp độ và lấy mẫu. Ghi mọi thứ ở mức DEBUG trong production tạo khối lượng khổng lồ và tốn tiền lưu trữ. Dùng slog.HandlerOptions{Level} để lọc cấp độ, cân nhắc sampling cho log tần suất cao (ví dụ chỉ ghi 1/100 log của một code path nóng). Structured logging làm log hữu ích hơn, không làm nó miễn phí — kỷ luật về cấp độ và lượng vẫn cần.

Ba ý mang về

  1. JSON truy vấn được, text thì không: đo thật jq lọc level==ERROR (4 dòng), latency_ms>100 (5 request), tổng amount=10.407.884 — so sánh số và tổng hợp chạy tin cậy vì mỗi trường có tên và kiểu, trong khi text thuần phải regex mong manh.
  2. trace_id nối log với trace: đo thật trace_id trong log ERROR được Jaeger API xác nhận là trace có thật (service order-svc) — thấy lỗi trong log là nhảy thẳng tới đúng trace, biến ba trụ cột rời rạc thành một hệ thống.
  3. Dùng đúng chỗ, giữ kỷ luật: text cho dev/JSON cho production (đổi handler, không sửa code); đẩy trường cardinality cao vào nội dung log chứ không index; và structured logging làm log hữu ích hơn chứ không miễn phí — vẫn cần cấp độ và lấy mẫu.

Nguồn

Phần sau ta biến metric thành hành động: alerting — viết rule cảnh báo trên Prometheus, hiểu vì sao ngưỡng tĩnh gây báo động giả, và cách for cùng tỉ lệ lỗi tạo cảnh báo đáng tin thay vì gây mệt mỏi.