Ghi log cho ứng dụng Node.js

Ghi log là một quá trình rất quan trọng để theo dõi và khắc phục sự cố cho các ứng dụng Node.js nói riêng và tất cả các ứng dụng nói chung. Chúng giúp theo dõi lỗi trong ứng dụng, giúp ích trong quá trình phân tích và tối ưu hiệu suất. Nhờ đó, các nhà phát triển ứng dụng có thể đưa ra những quyết định quan trọng trong việc cải tiến ứng dụng của mình.

Sự quan trọng của log

Các hệ thống lớn như hệ quản trị cơ sở dữ liệu, hệ điều hành đều ghi log chi tiết từng thao tác của người dùng.

Log lỗi sẽ rất cần thiết khi xảy ra lỗi, dựa vào đó có thể tìm ra được lỗi ở đâu, đoạn code nào để có phương án xử lý phù hợp. Rất nhiều trường hợp lỗi trên môi trường production không thể tái hiện trên local, chỉ có thể dựa vào log để tìm ra nguyên nhân.

Nếu ghi log sử dụng ứng dụng, khi ứng dụng bị phá hoại, có thể dễ dàng tìm ra thủ phạm. Nếu ghi log cho những đoạn code phức tạp, những tiến trình chạy ngầm, sẽ dễ dàng biết được trạng thái của các tiến trình đó, biết được tốc độ xử lý của các logic phức tạp.

Tóm lại, ghi log có rất nhiều lợi ích khác nhau.

Mặc dù việc ghi log cực kỳ quan trọng, nó thường bị xem nhẹ trong quá trình phát triển phần mềm. Người ta thường tập trung vào tính năng, vào trải nghiệm người dùng, vào công nghệ tiên tiến v.v… mà ít quan tâm đến việc ghi log.

Trong quá trình phát triển phần mềm, nếu làm việc trên máy cá nhân, các lập trình viên có thể dễ dàng in ra thông tin này, thông tin kia phục vụ cho việc debug hay phân tích ứng dụng. Với Node.js, một vài câu console.log có thể đem lại rất nhiều thông tin quan trọng. Thế nhưng, khi đã triển khai ứng dụng lên môi trường production hay staging, những dòng code như vậy sẽ phải xóa bỏ.

Lúc này, nếu cần debug hay tìm hiểu bất cứ điều gì, việc lấy thông tin từ ứng dụng sẽ cực kỳ khó khăn nếu không có log. Một ứng dụng đã triển khai cũng không dễ dàng để có thể bổ sung tính năng ghi log. Hơn nữa, để xảy ra vấn đề mới bắt đầu ghi log thì khác gì “mất bò mới lo làm chuồng”.

Các lập trình viên, những người trực tiếp làm việc với những logic nhỏ nhất của ứng dụng, nên rèn luyện thói quen ghi log. Việc ghi log nên được đưa vào từ những ngày đầu tiên của một dự án phần mềm.

Best practice khi ghi log

Mọi người đều nên ghi log

Log là quan trọng với tất cả mọi người, từ developer, DevOps, tới SysAdmin. Log hợp lý sẽ là cách cực hiệu quả để tăng hiệu suất làm việc. Developer sẽ tránh phải đọc lại code để tìm hiểu nguyên nhân lỗi. DevOps Engineer sẽ đọc log và biết nguyên nhân của lỗi do đâu, bug của ông dev hay là lỗi khi triển khai. SysAdmin cũng tương tự, chuẩn đoán lỗi từ log của các package và hệ điều hành là vô cùng quan trọng.

Lưu log càng lâu càng tốt

Việc lưu log ở đâu và trong bao lâu tùy thuộc vào tính chất, nghiệp vụ của ứng dụng. Nếu có thể, nên lưu log càng lâu càng tốt. Tuy nhiên, lưu trữ sẽ phát sinh nhiều chi phí, vì vậy với một số log không quá quan trọng, có thể suy nghĩ đến việc xóa bỏ chúng sau một khoảng thời gian nhất định.

Ví dụ như access log, sau một thời gian, có thể được sử dụng để phân tích. Sau đó, hầu như chúng không còn được sử dụng nữa. Để kiệm chi phí vận hành, chúng có thể được xóa đi. Có thể là 6 tháng, 1 năm, tùy thuộc mức độ quan trọng cũng như chi phí có thể bỏ ra.

Có nhiều loại log cần lưu cả đời. Những thông tin đơn hàng, thanh toán là những thông tin tối quan trọng với khách hàng. Nó nên được lưu trữ lâu dài.

Có nhiều cách khác nhau để lưu trữ log. Đơn giản nhất là lưu trực tiếp vào ổ cứng của server. Để đảm bảo hiệu suất của server cũng như phòng tránh sự cố đáng tiếc, log nên lưu ở một ổ cứng riêng biệt. Một cách khác là thuê các dịch vụ lưu trữ cloud. Hầu hết các nhà cung cấp dịch vụ cloud (AWS, Azure, v.v…) đều có dịch vụ lưu trữ lâu dài với chi phí hợp lý.

Ngoài ra, log có thể lưu vào các cơ sở dữ liệu chuyên dụng. Giải pháp này thường áp dụng với các doanh nghiệp có nhiều dịch vụ khác nhau cần được quản lý log tập trung để dễ theo dõi, tìm hiểu khi xảy ra sự cố.

Log phải có ý nghĩa

Đây là điểm quan trọng nhất. Nếu ghi log không có nghĩa thì thà không ghi còn hơn để tăng hiệu suất cho ứng dụng.

Log đủ thông tin

Log message phải mô tả đầy đủ, rõ ràng về sự kiện mà nó log. Trong hầu hết các trường hợp, log là những thông tin còn lại duy nhất của những gì đã diễn ra bên trong ứng dụng. Vì vậy, nó cần cung cấp thông tin đầy đủ, chính xác.

Hãy xem xét một ví dụ dưới đây:

Request failed

Log message này chẳng mang lại bất kỳ một giá trị gì, ngoài việc thông báo ứng dụng đã gặp lỗi. Như tôi đã nói, log thế này thà không log còn hơn. Nếu như có thể log ra những thông tin như dưới đây, mọi thứ sẽ khác hẳn:

Request POST to "https://example.com/api" failed. Response code: "429", response message: "too many requests".

Log này tốt hơn nhiều vì nó cung cấp thông tin đầy đủ về request lỗi, mã lỗi và thông báo lỗi từ server. Nếu tất cả log đều cung cấp được thông tin đầy đủ như vậy, việc điều tra log sau này sẽ rất dễ chịu.

Nhưng cũng cần chú ý rằng, thông tin cần đầy đủ những cũng phải ngắn gọn. Điều này sẽ giúp những người điều tra log khi đọc không bị choáng ngợp bởi quá nhiều thông tin. Log cũng nên có tính độc lập, không phụ thuộc vào các log trước đó.

Thêm thông tin về bối cảnh vào log

Bên cạnh log message, thì bối cảnh của log cũng nên được thêm vào. Điều này giúp người đọc log có thể khoanh vùng dễ dàng và có thể hình dung được sự kiện diễn ra như thế nào. Ngoài ra, những thông tin bổ sung này có thể dùng để lọc ra những log cần thiết cho việc điều tra trong vô số log của cả ứng dụng.

Ví dụ, một số thông tin như sau nên được thêm vào (có thể còn nữa, tùy thuộc vào đặc thù từng ứng dụng):

• user id hoặc các thông tin tương tự
• mã sản phẩm, mã giao dịch
• thời điểm, thời gian diễn ra sự kiện
• module xử lý sự kiện

Lựa chọn log level

Việc sử dụng các log level khác nhau rất phổ biến trong thế giới phần mềm. Sử dụng log level thích hợp với từng thông tin sẽ giúp phân loại thông tin, các sự kiện cũng như bối cảnh của chúng. Log level cũng giúp chúng ta dễ dàng phân biệt được đâu là log của lỗi, những vấn đề cần giải quyết ngay, đâu là log thông tin đơn thuần.

Dưới đây là những level thường gặp:

• Fatal: các lỗi nghiêm trọng, thậm chí là đã gây ra gián đoạn ứng dụng, dịch vụ.
• Error: các event trên hệ thống đã gây ra lỗi tương đối lớn, có thể gây ảnh hưởng đến trải nghiệm của người dùng.
• Warn: các lỗi tiềm ẩn, có thể gây ra lỗi nhưng chưa ảnh hưởng đến trải nghiệm của người dùng.
• Info: mang tính chất cung cấp thông tin chung, không nên mang ý nghĩa chỉ định lỗi. Trường hợp thường dùng của level này là log thông tin về logic khó, các tiến trình nặng, tốn thời gian.
• Debug: dùng để debug, thường dành cho developer.
• Trace: ghi lại mọi thông tin về hoạt động của ứng dụng

Việc lựa chọn đúng log level sẽ giúp trích xuất và lưu trữ log chính xác hơn. Ví dụ, thông thường, các ứng dụng sẽ thiết lập lưu các log có level info trở lên. Những log ở level ít quan trọng hơn như debug hay trace sẽ không được trích xuất và lưu trong file log (dù trong code vẫn ghi log).

Nhưng khi cần điều tra thêm thông tin (ví dụ lỗi không thể tái hiện được), thiết lập có thể dễ dàng thay đổi để trích xuất nhiều log hơn, theo dõi nhiều thông tin hơn.

Viết log thân thiện với máy tính

Log thường được ghi dưới dạng plain text, thế nhưng không phải thích log thế nào cũng được. Log nên được viết có định dạng, có format nhất định để có thể dễ dàng xử lý bằng máy tính. Vì thực sự, con người làm việc với log không nhiều bằng máy tính.

Với những ứng dụng nhỏ, hoặc khi cần điều tra một lượng log nhỏ, việc đọc log có thể thực hiện thủ công. Lúc này, dù log không có định dạng nhất định vẫn có thể hiểu được.

Nhưng khi lượng log lớn, việc đọc log thủ công là không thể. Lúc này, người điều tra log có thể viết các tool, script để xử lý log đơn giản hơn. Hơn nữa, log có định dạng cũng có thể dễ dàng sàng lọc để tìm ra những log cần thiết (giữa rất nhiều log của cả ứng dụng) cho việc điều tra hơn.

Ngoài ra, với những ứng dụng lớn, sẽ có những công cụ phân tích log chuyên dụng. Lúc này, log nên có định dạng thân thiện với máy tính thì mới có thể tích hợp với những công cụ này.

Log thân thiện với người đọc

Các log cần thân thiện với máy tính nhưng cũng cần phải thân thiện với con người 😵‍💫. Vì sẽ có những trường hợp máy móc không thể thay thế con người, nhất là trong trường hợp phải điều tra lỗi. Lúc đó, sẽ có những người phải trực tiếp đọc log.

Tưởng tượng có những lỗi xảy ra lúc nửa đêm, rạng sáng cần điều tra gấp. Vào đọc log thấy toàn thông tin để “máy” đọc, còn “người” nhìn vào không hiểu gì, đã stress lại càng stress.

Công việc IT đã có nhiều áp lực, những việc gì có thể tránh được thì nên tránh. Ví dụ như việc đọc và ghi log, có thể dễ dàng phòng tránh ngay từ những bước đầu tiên. Để thông tin dễ đọc, dễ hiểu có một số gợi ý như sau:

• Dùng câu cú ngắn gọn, rõ ràng.
• Dữ liệu ngày tháng nên dùng định dạng thống nhất, tốt nhất là sử dụng chuẩn format ISO8601.
• Sử dụng đúng và hợp lý log level.
• Log lỗi thì nên có trace back thay vì chỉ một vài thông tin chung chung.

Che các thông tin nhạy cảm

Tuyệt đối không được để lộ các thông tin nhạy cảm của server hay thông tin người dùng trong log. Một số thông tin có thể:

• Mật khẩu
• Thông tin thẻ ngân hàng
• Private key, Secret Key
• Access Token
• Thông tin của khách hàng như email, tên, số điện thoại, địa chỉ…

Log có thể được truy cập từ nhiều bên, nguy cơ bị lộ các thông tin nhạy cảm rất cao. Để phòng tránh tối đa nguy cơ bị khai thác thông tin từ log, một số ngân hàng và doanh nghiệp tài chính thậm trí còn mã hóa log của mình 😎.

Ghi log cho ứng dụng Node.js

Chọn thư viện

Những công cụ có sẵn như console.log có thể quen thuộc và dễ dàng sử dụng với lập trình viên. Nhưng chúng không thích hợp để ghi log. Có thể thích hợp khi làm việc ở local, console.log thiếu những tính năng quan trọng trong việc ghi log ứng dụng trên production.

Ví dụ, console không hỗ trợ các log level khác nhau. Mặc dù cú pháp của nó cho phép điều đó, những hàm như console.warn, console.debug hay console.error có tác dụng gần như nhau, chỉ đơn giản là in thông tin ra terminal (đầu ra chuẩn) mà thôi.

Các thư viện ghi log cung cấp nhiều tính năng quan trọng hơn, ví dụ như định dạng log, ghi log tập trung. Hầu hết những thư viện này cho phép người dùng lựa chọn nơi ghi log (file, cơ sở dữ liệu, v.v…), một số còn cho phép gửi thông tin log đến các máy chủ chuyên dụng.

Để chọn thư viện phù hợp, một vài yếu tố cần suy xét: định dạng log, khả năng lưu trữ, hiệu suất. Vì ghi log sẽ xuất hiện hầu như ở mọi nơi trong ứng dụng, hiệu suất của nó có thể ảnh hưởng đến logic chính của ứng dụng.

Đối với một ứng dụng Node.js, có nhiều lựa chọn khác nhau được cộng đồng tin tưởng. Hầu hết chúng có tính năng tương tự nhau. Một vài cái tên phổ biến:

• Winston: Thư viện phổ biến nhất để ghi log. Cho phép tùy chỉnh và cấu hình rất linh hoạt.
• Log4js: Thư viện hợp nhất với Express, có khả năng ghi log màu sắc ra terminal.
• Pino: Thư viện tập trung vào hiệu suất. Đây là thư viện được đánh giá có hiệu suất tốt nhất.
• Bunyan: Một thư viện với rất nhiều tính năng hay, trong đó có ghi log theo định dạng JSON và có công cụ (CLI) cho phép xem log trực tiếp.

Trong nội dung bài viết này, tôi sẽ sử dụng winston. Tôi lựa chọn đơn giản vì đây là thư viện phổ biến nhất. Để cài đặt, có thể dùng lệnh:

$ yarn add winston

Log level

Thư viện winston mặc định cung cấp các log level sau, theo thứ tự giảm dần của mức độ nghiêm trọng:

{
    "error": 0,
    "warn": 1,
    "info": 2,
    "http": 3,
    "verbose": 4,
    "debug": 5,
    "silly": 6
}

Nếu thiết lập mặc định của winston không đáp ứng được yêu cầu, người dùng có thể tự định nghĩa các level của riêng mình:

const { createLogger, format, transports } = require("winston");

const logLevels = {
    fatal: 0,
    error: 1,
    warn: 2,
    info: 3,
    debug: 4,
    trace: 5,
};

const logger = createLogger({
    levels: logLevels,
    transports: [new transports.Console()],
});

Để log một thông tin với level nào đó, thư viện sẽ cung cấp các hàm tương ứng:

logger.info("System launch");
// {"message":"System launch","level":"info"}
logger.fatal("A critical failure!");
// {"message":"A critical failure!","level":"fatal"}

Thư viện winston cho phép người dùng lựa chọn level nào để trích xuất và lưu lại log. Mức level này có thể thay đổi bằng cách dùng biến môi trường.

const logger = winston.createLogger({
    level: "warn",
    levels: logLevels,
    transports: [new transports.Console({ level: "info" })],
});

Định dạng log

Định dạng log nên được lựa chọn sao cho có thể dễ dàng được đọc bởi cả con người và máy tính. JSON là một định dạng cho phép con người có thể đọc hiểu, đồng thời có thể xử lý dữ liệu tự động bằng nhiều công cụ cũng như ngôn ngữ lập trình khác nhau.

Mặc định, winston sẽ sử dụng JSON với hai trường: message, level. Người dùng có thể thêm các trường khác với winston.format. Thư viện logform được dùng để làm việc với các định dạng khác nhau. Ví dụ, để thêm trường timestamp như sau:

const { createLogger, format, transports } = require("winston");

const logger = createLogger({
    format: format.combine(format.timestamp(), format.json()),
    transports: [new transports.Console({})],
});

Sau này, mọi log sẽ có thêm trường timestamp như sau:

{"message":"Connected to DB!","level":"info","timestamp":"2023-09-24T22:35:27.758Z"}
{"message":"Payment received","level":"info","timestamp":"2023-09-24T22:45:27.758Z"

Có thể đặt một trường với dữ liệu mặc định khi tạo logger cho từng component. Thông này sẽ rất hữu ích để biết được sự kiện được xử lý bởi module nào, hay process nào.

const logger = createLogger({
    format: format.combine(format.timestamp(), format.json()),
    defaultMeta: {
        module: "BillingService",
    },
    transports: [new transports.Console({})],
});

Trường module sẽ được thêm vào log và sẽ luôn có giá trị mặc định là module hiện tại:

{"message":"Order 1234 was processed successfully","level":"info","module":"BillingService","timestamp":"2023-09-24T10:56:14.651Z"}

Không chỉ vậy, khi cần nhiều thông tin hơn, winston còn cho phép đưa context vào log. Đây là nơi chứa những thông tin về bối cảnh của log. Với những ứng dụng lớn và phức tạp, việc này sẽ cực kỳ cần thiết khi điều tra lỗi.

Để đưa context và log, cần tạo một object chứa các thông tin về log đó và đưa nó vào child loggers:

const ctx = {
    userId: "001001",
    productId: "101101",
};

logger.child({ context: ctx }).info('Order 1234 was processed successfully');
// {"context":{"userId":"001001","productId":"101101"},"message":"Order 1234 was processed successfully","level":"info","module":"BillingService","timestamp":"2023-09-24T12:20:13.249Z"}

Log để đánh giá hiệu suất

Mục đích chính của log là để điều tra, truy vết khi có vấn đề xảy ra. Nhưng điều đó không có nghĩa là log không thể được dùng cho mục đích khác. Log cũng có thể được sử dụng để đánh giá hiệu suất, cung cấp những thống kê quan trọng về hoạt động của hệ thống.

Ví dụ, có thể log những thông tin về hoạt động của hệ thống như user đăng nhập, tìm kiếm, tạo đơn hàng, v.v… Trong trường hợp thiếu những công cụ chuyên theo dõi hiệu suất, những thông tin từ log như thời gian để hệ thống xử lý truy vấn, thời gian một chức năng hoàn thành cũng có thể được sử dụng.

Thư viện winston cung cấp cơ chế profile, cho phép làm việc đó rất dễ dàng:

logger.profile("test", { level: "info" });

// Returns an object corresponding to a specific timing
const profiler = logger.startTimer();

setTimeout(() => {
    // End the timer and log the duration
    profiler.done({ message: "Logging message" });
}, 1000);

Một trường mới, durationMs, sẽ được thêm vào log:

{"message":"Logging message","level":"info","durationMs":1001,"timestamp":"2023-09-24T14:17:55.097Z"}

Tự động log lỗi

Khi có một exception hoặc promise bị reject mà không được xử lý, việc log ra những thông tin liên quan là cực kỳ cần thiết. Log là những thông tin còn lại để biết chuyện gì đã xảy ra, từ đó có thể đưa ra những phương án phù hợp.

Đối với ứng dụng, trong những trường hợp đó, nên có cơ chế theo dõi và khởi động lại, tránh để ứng dụng crash, ảnh hưởng đến người dùng.

Tuy nhiên, do exception không được xử lý, việc log thông tin không đơn giản. Rất may, thư viện winston cho phép tự động log lỗi cho những trường hợp như vậy, chỉ cần thêm một số cấu hình khi tạo logger như sau:

const logger = createLogger({
    transports: [new transports.File({ filename: "file.log" })],
    exceptionHandlers: [new transports.File({ filename: "exceptions.log" })],
    rejectionHandlers: [new transports.File({ filename: "rejections.log" })],
});

Như trong ví dụ trên, những exception không được xử lý sẽ được log vào file exceptions.log, còn những promise bị reject (mà không được xử lý) sẽ được log vào file rejections.log. Thông tin log sẽ tự động được ghi, bao gồm stack trace cũng như những thông tin liên quan đến process hay bộ nhớ liên quan.