Note: see the link below for the English version of this article.

https://duongnt.com/structured-log/

Structured logging là gì

Logging là một trong những công cụ hữu ích nhất của mỗi lập trình viên. Nếu thiếu logging, việc theo dõi trạng thái hệ thống, đo hiệu năng, hay sửa lỗi sẽ khó khăn hơn rất nhiều, nếu không muốn nói là sẽ trở thành bất khả thi. Điều này càng đúng hơn nếu hệ thống của ta được cấu thành từ nhiều microservice, trong đó mỗi service lại có nhiều instance hòng tăng tính khả dụng

Logging theo phong cách truyền thống

Cách logging truyền thống là ghi tất cả dữ liệu ra các file. Tuy nhiên cách làm này có nhược điểm lớn, nó không bảo toàn được toàn bộ thông tin ban đầu trong log. Giả sử ta có một file log lớn trong đó có nhiều message như dưới đây.

<timestamp> Warn: CPU Usage percentage exceeded 50% for node A
<timestamp> Warn: Memory Usage exceeded 50% for node B

Ta có thể dùng câu lệnh grep %node A% để trích ra tất cả message về NodeA, ta cũng có thể dùng grep %exceeded 50% để trích toàn bộ các cảnh bảo khi một node nào đó sử dụng quá 50% tài nguyên. Cách làm này cho phép ta tìm được cả những message thỏa mãn điều kiện phức tạp như node A sử dụng quá 50% CPU. Tuy nhiên, phương pháp này tương đối phức tạp, tốn thời gian và dễ dẫn đến nhầm lẫn.

Structured logging

Với structured logging, thay vì lưu dữ liệu dưới dạng text thông thường, log được lưu với format đã được quy định trước. Hai message ví dụ trong phần trước sẽ được lưu dưới dạng sau đây.

{
   "Timestamp":"<timestamp>",
   "Level":"Warning",
   "MessageTemplate":"{ResourceName} percentage exceeded {ResourcePercentage}% for node {NodeName}",
   "Properties":{
      "ResourceName":"CPU Usage",
      "ResourcePercentage": 50,
      "NodeName": "A"
   }
},
{
   "Timestamp":"<timestamp>",
   "Level":"Warning",
   "MessageTemplate":"{ResourceName} percentage exceeded {ResourcePercentage}% for node {NodeName}",
   "Properties":{
      "ResourceName":"Memory Usage",
      "ResourcePercentage": 50,
      "NodeName": "B"
   }
}

Việc sử dụng structured logging cho phép ta viết câu query trên log như thể query dữ liệu trong DB. VD: để tìm tất cả cảnh báo khi node A sử dụng quá 50% CPU, ta chỉ cần dùng query này NodeName = A and ResourceName = "CPU Usage" and ResourcePercentage > 50. Vì log của ta có format cố định nên các phần mềm dễ xử lý chúng hơn, ta có thể sử dụng nhiều công cụ để đọc, phân tích và tìm ra quy luật từ log một cách tự động.

Structured logging với Seq

Để ta sẽ sử dụng Seq, một hệ thống logging tập trung, để thử các chức năng của structured logging. Đường link tải bản dùng thử của Seq nằm tại đây. Ngoài Seq ta cũng có nhiều lựa chọn khác như SumoLogic hay Datadog.

Sau khi cài đặt, theo mặc định Seq sẽ chạy ở cổng 5341. Trang chủ của nó như sau.

Tôi đã viết sẵn một phần mềm sinh log tự động, đường link tại đây. Các bạn có thể clone repository này và chạy câu lệnh dưới đây để tạo 100 message, ta sẽ dùng chúng trong phần dưới.

dotnet run Seq

Sau khi chạy câu lệnh trên, trang Seq sẽ như sau.

Chú ý là mặc dù ta đang sử dụng structured logging, Seq vẫn hiển thị log giống như log truyền thống, các chức năng của structured log chỉ được sử dụng khi ta gọi đến.

Sau đây ta sẽ chạy thử một số query đơn giản.

Tìm tất cả message khi NodeA dùng quá 50% bộ nhớ và toàn bộ message khi NodeB dùng dưới 50& bộ nhớ.

ResourceName='Memory Usage' and ((NodeName='NodeA' and ResourcePercentage > 50) or (NodeName='NodeB' and ResourcePercentage <50))

Thống kê tất cả log của NodeB, so sánh lượng bộ nhớ và CPU mà node này sử dụng nhằm tìm ra mối liên quan giữa chúng.

select count(*) as Event
from stream
where NodeName='NodeB'
group by ResourceName, time(5s)

Ta cũng có thể tìm kiếm bằng text giống như trong log truyền thống.

"percentage exceeded 8"

Sử dụng Serilog để xuất structured log với C#

Trong bài này ta dùng Serilog để xuất structured log với C#, tuy nhiên ta cũng có thể lựa chọn một vài library khác như NLog hay Microsoft.Extensions.Logging…

Cài đặt các library cần thiết

Đầu tiên ta cần cài Serilog.

dotnet add package Serilog --version 2.10.0

Sau đó ta cần cài một library hỗ trợ để sử dụng Serilog cùng với hệ thống logging của .Net Core.

dotnet add package Serilog.Extensions.Hosting --version 4.1.2

Ta còn cần cài đặt các sink, đây là đích mà ta sẽ ghi log vào. Trong môi trường thực tế, ta sẽ sử dụng hệ thống log tập trung như Seq, tuy nhiên ta sẽ cài thêm hai sink khác để ghi log ra file hoặc console.

dotnet add package Serilog.Sinks.Seq --version 5.0.1 // <- Seq sink
dotnet add package Serilog.Sinks.File --version 4.1.0 // <- File sink
dotnet add package Serilog.Sinks.Console --version 3.1.1 // <- Console sink

Thiết lập cho Serilog

Tạo một LoggerConfiguration và thiết lập để nó ghi log ra server Seq mà ta vừa cài đặt trong phần “.

var configuration = new LoggerConfiguration();
configuration.WriteTo.Seq("http://localhost:5341/"); // <- dùng cổng mặc định của Seq

Dùng LoggerConfiguration để tạo Logger và gán nó vào biến ILogger của Serilog.

Log.Logger = configuration.CreateLogger();

Cuối cùng ta tích hợp Serilog vào hệ thống log của .Net Core.

services.AddLogging(logBuilder => logBuilder.AddSerilog(dispose: true))

Giờ đây ta có thể dùng Serilog để ghi structured log.

_logger.Log(LogLevel.Information, "Hello to {Name}", "Nguyen Thai Duong");

Kết quả sẽ như sau.

Đối với Seq, log trên được lưu dưới dạng sau (múi giờ UTC).

{
   "@t":"2021-06-15T13:43:26.3719578Z",
   "@mt":"Hello to {Name}",
   "@m":"Hello to Nguyen Thai Duong",
   "@i":"8a4e9e4c",
   "Name":"Nguyen Thai Duong",
   "SourceContext":"StructuredLogGenerator.LogGenerator"
}

Xuất log ra file hoặc console

Hệ thống log tập trung như Seq là giải pháp tốt nhất trong môi trường thực tế, tuy nhiên đôi khi ta cần xuất log ra file hoặc console để debug.

Để ghi ra console, ta đổi LoggerConfiguration thành như sau.

var configuration = new LoggerConfiguration();
configuration.WriteTo.Console(); // <- dùng console làm sink

Kết quả của câu lệnh.

_logger.Log(LogLevel.Information, "Hello to {Name}", "Nguyen Thai Duong");

Sẽ như sau.

Ta có thể đổi format của log trong console thành JSON.

var configuration = new LoggerConfiguration();
configuration.WriteTo.Console(new JsonFormatter()); // <- dùng formatter ở đây

Tương tự trên, để xuất log ra file, ta đổi LoggerConfiguration thành.

var configuration = new LoggerConfiguration();
configuration.WriteTo.File("C:/duong.log"); // <- xuất log ra "C:/duong.log"

Có lẽ các bạn cũng đã đoán được là ta có thể ghi log dưới dạng JSON vào file.

var configuration = new LoggerConfiguration();
configuration.WriteTo.File(new JsonFormatter(), "C:/duong.log");

Kết thúc

Trên đây chúng ta đã thử qua một phần rất nhỏ của structured logging. Tôi hy vọng rằng bài viết này sẽ khiến những ai chưa thử qua structured logging cảm thấy hứng thú để dùng thử nó.