Phần trước ta đã có log JSON có cấu trúc, lọc được bằng jq. Nhưng ngay khi đưa lên production, một vấn đề mới lộ ra. Server xử lý nhiều request đồng thời, mỗi request chạy trên một goroutine riêng, và tất cả cùng ghi log vào một dòng chảy. Kết quả: log của request A, B, C, D đan xen nhau theo đúng thứ tự goroutine nào được lịch cho chạy. Khi một request cụ thể lỗi và bạn muốn xem nó đã đi qua những bước nào, bạn nhìn vào một mớ hỗn độn — dòng "nhận request" của cái này, "truy vấn DB" của cái kia, "trả lỗi" của cái thứ ba, không có gì nối chúng lại.

Lời giải là log correlation: gắn một định danh chung — trace_id (hay request_id) — cho mọi dòng log phát ra trong cùng một request. Khi đó, dù log có đan xen thế nào, chỉ cần lọc theo một trace_id là bạn dựng lại được trọn vẹn hành trình của đúng request đó. Câu hỏi kỹ thuật là: làm sao để cái ID đó "theo chân" request qua mọi hàm mà không phải truyền tay nó vào từng lời gọi log? Câu trả lời trong Go là context.Context. Bài này (phần 2 loạt Observability) đo thật cách làm.

Cơ chế: context mang ID, handler tự gắn

context.Context trong Go được thiết kế đúng cho việc này: nó đi xuyên suốt một request (theo quy ước, hàm nào trong đường xử lý request cũng nhận ctx làm tham số đầu). Ta nhét trace_id vào context ở biên (nơi request bắt đầu), và nó tự động có mặt ở mọi hàm sâu bên trong.

Mảnh ghép còn thiếu là làm sao để slog tự đọc trace_id từ context mà không phải viết slog.String("trace_id", id) ở mỗi lời gọi log. Giải pháp gọn: một slog.Handler tùy biến bọc quanh handler thật, và trong hàm Handle nó móc trace_id ra khỏi context rồi chèn vào bản ghi:

Ảnh chụp đoạn mã nền tối minh hoạ log correlation gắn trace_id vào context, khối trên ContextHandler là struct nhúng slog.Handler hàm Handle nhận ctx và record r nếu lấy được id kiểu chuỗi từ ctx.Value traceKey thì gọi r.AddAttrs slog.String trace_id id để mọi log tự mang trace_id rồi gọi handler gốc, khối dưới mỗi request một trace_id truyền xuyên suốt qua context tạo ctx bằng withTrace context.Background trace-0007 sinh ở biên mọi bước dùng InfoContext ctx nhan request truy van DB với slog.String buoc db tra ket qua với slog.Int status 200 handler tự chèn trace_id

Hình 1: ContextHandler nhúng một slog.Handler và override Handle — nó đọc trace_id từ ctx.Value rồi AddAttrs vào bản ghi trước khi chuyển xuống handler gốc. Nhờ vậy, mọi lời gọi l.InfoContext(ctx, ...) trong request đều tự mang trace_id, không cần lặp lại thủ công.

Điểm mấu chốt là InfoContext(ctx, ...) (chứ không phải Info(...)): biến thể có Context truyền ctx xuống tận Handle, nơi handler tùy biến móc trace_id ra. Lập trình viên viết log như bình thường; việc gắn ID là tự động và tập trung một chỗ.

Đo thật trong go-lab

Mình chạy trong go-lab (golang 1.23) hai kịch bản. Đầu tiên là không có trace_id: 5 request đồng thời, mỗi cái ghi 3 dòng log. Sau đó là có trace_id: nâng lên 50 request đồng thời (150 dòng log), rồi dùng jq lọc ra hành trình của đúng một request.

Ảnh chụp bảng kết quả chạy thật trong go-lab output thật golang 1.23 50 request đồng thời 150 dòng log, khối một KHÔNG trace_id log của các request đan xen msg nhan request req 5 msg nhan request req 2 chú thích req nào của req nào không tách được msg truy van DB req 5 msg tra ket qua req 1 chú thích thứ tự trộn lẫn theo lịch chạy goroutine, khối hai và ba CÓ trace_id jq lọc ra đúng chuỗi log của một request mọi dòng đều mang trace_id 150 trên 150 dòng lọc 1 request jq select trace_id bằng trace-0007 ra ba dòng nhan request truy van DB buoc db tra ket qua status 200 đều mang trace_id trace-0007 ra đúng 3 bước đúng thứ tự của riêng request đó kiểm toàn bộ 50 request riêng biệt mỗi trace_id xuất hiện đúng 3 lần phân bố 50 nhân 3 dòng bằng 150 dòng không sót không lẫn

Hình 2: Kết quả thật — không trace_id: log của các request đan xen theo lịch goroutine, không tách được. Có trace_id: cả 150/150 dòng đều mang ID; jq 'select(.trace_id=="trace-0007")' trả về đúng 3 bước của request đó đúng thứ tự; và kiểm toàn bộ, 50 request riêng biệt, mỗi trace_id xuất hiện đúng 3 lần.

Con số xác nhận cơ chế hoạt động chính xác:

  • Không ID: log đan xen. Với các request chạy song song, thứ tự dòng log là thứ tự goroutine được lịch cho chạy — nhan request req=5, rồi nhan request req=2, rồi truy van DB req=5... Muốn theo dõi request số 3, bạn phải mắt thường nhặt các dòng có req=3 rải rác. Ở quy mô thật (hàng nghìn request/giây, log gộp từ nhiều máy), việc này bất khả thi.
  • Có ID: lọc một câu ra trọn hành trình. Cả 150 dòng đều mang trace_id. jq 'select(.trace_id=="trace-0007")' trả về đúng 3 dòng của request đó — nhan request → truy van DB (bước db) → tra ket qua (status 200) — đúng thứ tự logic của riêng nó, bất kể chúng nằm ở đâu trong 150 dòng.
  • Kiểm toàn vẹn: không sót, không lẫn. Đếm phân bố cho thấy 50 trace_id riêng biệt, mỗi cái xuất hiện đúng 3 lần (50 × 3 = 150). Không request nào bị mất log, không dòng nào bị gán nhầm ID — vì context đảm bảo mỗi goroutine mang đúng ID của nó, và handler đọc đúng từ context đó.

Đây là nền tảng của distributed tracing (phần 7): trace_id chính là sợi chỉ nối mọi thứ. Có nó rồi, log không chỉ là dữ liệu rời rạc mà trở thành dòng thời gian có thể lần theo của từng request.

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

Phải truyền context xuyên suốt — kỷ luật, không phải phép màu. Cơ chế này chỉ hoạt động nếu ctx được truyền qua mọi hàm trong đường xử lý request, và mọi lời gọi log dùng ...Context(ctx, ...). Một hàm quên nhận ctx, hoặc gọi l.Info() thay vì l.InfoContext(ctx, ...), là dòng log đó rơi mất trace_id — đúng lúc bạn cần nó. Đây là lý do quy ước Go đặt ctx context.Context làm tham số đầu tiên của hàm: để nó luôn có mặt. Chi phí là kỷ luật code, nhưng đó là chi phí đáng trả.

Sinh ID ở biên và nhận từ header để xuyên nhiều service. trace_id nên được sinh một lần ở biên hệ thống — thường trong một middleware HTTP chạy đầu mỗi request. Quan trọng hơn: nếu request đến đã mang một trace ID (từ service gọi nó), middleware phải đọc ID đó từ header và dùng tiếp thay vì sinh mới — nhờ vậy một request đi qua nhiều service vẫn giữ cùng một trace_id, và bạn lần được toàn bộ chuỗi liên-service. Chuẩn hoá việc này là W3C Trace Context với header traceparent (chứa trace-id, span-id, cờ) — dùng chuẩn thay vì tự đặt tên header để tương thích với mọi công cụ tracing.

Đừng lạm dụng context.Value. context.Value tiện nhưng dễ bị lạm dụng thành một "túi đựng đồ" truyền mọi tham số ngầm — đó là anti-pattern làm code khó hiểu và khó test (phụ thuộc ẩn). Quy tắc từ chính tài liệu Go: chỉ dùng context.Value cho dữ liệu cross-cutting đi kèm request (request-scoped) như trace_id, thông tin xác thực, deadline — không dùng để truyền tham số nghiệp vụ (những thứ đó nên là tham số hàm tường minh). trace_id là ví dụ mẫu mực của thứ nên nằm trong context: nó liên quan tới mọi tầng nhưng không phải logic của tầng nào.

Ba ý mang về

  1. Log song song đan xen — cần một ID chung để tách: đo thật, 50 request đồng thời tạo 150 dòng log trộn lẫn theo lịch goroutine; không có trace_id thì không cách nào dựng lại hành trình của một request cụ thể.
  2. context mang trace_id, một slog.Handler tùy biến tự gắn nó: đo thật, sau khi thêm ContextHandler, cả 150/150 dòng mang ID, và jq 'select(.trace_id=="trace-0007")' trả về đúng 3 bước đúng thứ tự của request đó; kiểm toàn bộ, 50 trace_id mỗi cái xuất hiện đúng 3 lần — không sót, không lẫn.
  3. Đây là kỷ luật, và là nền của tracing xuyên service: phải truyền ctx qua mọi hàm và log bằng ...Context; sinh ID ở biên nhưng đọc lại từ header (traceparent chuẩn W3C) để xuyên nhiều service; và chỉ dùng context.Value cho metadata request-scoped như trace_id, không cho tham số nghiệp vụ.

Nguồn

Phần sau ta bước sang trụ cột thứ hai — metric: dùng expvar trong thư viện chuẩn để đếm throughput và số request đang xử lý (inflight), và đo thật khác biệt giữa một con số cộng dồn (counter) và một con số lên xuống (gauge).