Log rất quan trọng trong ứng dụng vậy ghi log thế nào cho đúng?

Nov 6, 2021 log ghi-log logging prod
Chia sẻ qua:

Overview

1. Log là gì? Tại sao cần ghi log?

Log là các bản ghi, dữ liệu về sự kiện xảy ra trong khi ứng dụng của bạn hoạt động.

Tại sao cần phải ghi log?

Trong quá trình hoạt động luôn luôn có những sự cố xảy ra, các ngoại lệ các bạn chưa tính đến và khi đó log thể hiện vai trò của mình. Nó giúp bạn tìm ra nguyên nhân sự cố giúp bạn khắc phục nó. Trong môi trường develop các bạn hoàn toàn có thể sử dụng các công cụ mà IDE hỗ trợ để debug. Nhưng trên môi trường product bạn không thể tái hiện được lỗi xảy ra. Ví dụ: Khách hàng chuyển tiền không thành công bạn không thể yêu cầu khách hàng chuyển lại để bạn kiểm tra được. Vậy nếu ghi log đúng bạn có thể thông qua đó tìm ra nguyên nhân lỗi để khắc phục.

2. Chúng ta cần ghi log những gì?

Dữ liệu đầu vào và đầu ra

Thường là API Enpoint, Controller, Listener(DB, message queue)... sẽ ghi lại các thông tin liên quan tới dữ liệu đầu vào và kết quả trả ra ngoài.

Với một API bạn có thể ghi các thông tin như request/response body, header, ip, parameters, url, thông tin người dùng, thời gian xử lý.

Với các input từ database, message queue nào đó thì bạn có thể ghi input object và output object.

Chú ý: Mỗi một luồng xử lý bạn cần tạo cho nó một ID để phục vụ cho việc đọc log dễ dàng hơn.

Ví dụ như sau:

1INFO: Add user with request { "user": "test1", "email": "[email protected]" }
2INFO: Add user with request { "user": "test2", "email": "[email protected]" }
3INFO: Get connection to database successfully.
4INFO: Success
5INFO: Get connection to database successfully
6ERROR: Email already exist

Như ví dụ trên mình có 2 request tạo user đồng thời và 1 request thành công, một request thất bại nhưng bạn sẽ không biết được cái nào thành công, cái nào thất bại. Nếu lượng request nhiều lên nữa và log gồm nhiều thông tin thì sẽ rất khó để có thể đọc và tìm ra lỗi.

Khi tạo ID cho mỗi request và ghi vào log chúng ta sẽ dễ dàng có thể tra cứu được luồng xử lý.

1[00000001] - INFO: Add user with request { "user": "test1", "email": "[email protected]" }
2[00000002] - INFO: Add user with request { "user": "test2", "email": "[email protected]" }
3[00000002] - INFO: Get connection to database successfully.
4[00000002] - INFO: Success
5[00000001] - INFO: Get connection to database successfully.
6[00000001] - ERROR: Email already exist

Với các thư viện ghi log của JAVA (với các framework blocking sử dụng thread cho từng request như Spring) thì khá dễ dàng

 1SLF4j: MDC
 2LOG4J2: ThreadContext
 3
 4public void filter() {
 5    String logId = generateLogId();
 6    MDC.put("log_id", logID);
 7    ///
 8    /// Do some things 
 9    ///
10    // Nếu hàm có thể văng exception thì cho vào block try finnally
11    MDC.clear();
12}

Với các hàm non-blocking thì các bạn sẽ phải truyền logId thông qua param và ghi thủ công. (Nếu bạn tìm được cách khác dễ dàng hơn thì báo mình nhé).

Đây là một hàm helper khi dùng vertx, khi request vào thì sẽ set logId vào RoutingContext và khi hàm trả lại kết quả thì lấy logId ra và sử dụng.

 1package com.truongnq;
 2
 3import io.vertx.core.AsyncResult;
 4import io.vertx.core.Handler;
 5import io.vertx.core.buffer.Buffer;
 6import io.vertx.ext.web.RoutingContext;
 7import lombok.extern.slf4j.Slf4j;
 8import com.truongnq.Constant;
 9
10import java.util.function.Function;
11
12/**
13 * @author truongnq
14 * Date: 19/01/2021
15 */
16@Slf4j
17public class ResultHandler {
18
19    private ResultHandler() {
20    }
21
22    /**
23     * This method generates handler for async methods in REST APIs.
24     */
25    public static <T> Handler<AsyncResult<T>> create(RoutingContext context, Function<T, Buffer> converter) {
26        return create(context, converter, 200);
27    }
28
29    public static <T> Handler<AsyncResult<T>> create(RoutingContext ctx,
30                                                     Function<T, Buffer> converter,
31                                                     int status) {
32        return res -> {
33            // Lấy logId và thời gian request từ context
34            final String logId = ctx.get(Constant.LOG_TOKEN_NAME);
35            final Long startTime = ctx.get(Constant.REQUEST_TIME);
36            try {
37                if (res.succeeded()) {
38                    Buffer response = converter.apply(res.result());
39                    log.info("[{}] - Response: {}", logId, response);
40                    ctx.response().setStatusCode(status).end(response);
41                } else {
42                    ctx.fail(res.cause());
43                }
44            } catch (Throwable cause) {
45                ctx.fail(cause);
46            } finally {
47                long processTime = System.currentTimeMillis() - startTime;
48                log.info("[{}] - Request finish in: {}", logId, processTime);
49            }
50        };
51    }
52}

Các bước xử lý trong các hàm, các service

Ngoài các đầu tiếp nhận dữ liệu từ các nguồn bên ngoài ứng dụng thì các service, các hàm nội bộ cũng nên ghi log input và output. Thường được ghi với các mức log thấp hơn như DEBUG. Nó sẽ hỗ trợ tìm và khắc phục lỗi liên quan tới logic và nghiệp vụ. Ghi rõ các bước xử lý, và nếu có nhiều case trả về cùng kết quả cần ghi thêm nguyên nhân.

 1// Đây là một hàm trong websocket server sử dụng Netty.
 2// Hàm gửi thông báo tới các websocket client
 3public boolean notify(Set<ChannelId> sessionIds, @Nonnull Notify<?> notifyMessage) {
 4    long logId = notify.getId();
 5    if (null == sessionIds || sessionIds.isEmpty()) {
 6        // Thành công nhưng đây là case đặc biệt vì không có client nào được truyền vào.
 7        log.debug("[{}] - Empty sessions", logId);
 8        return true;
 9    }
10    // Chuẩn bị dữ liệu để gửi
11    log.debug("[{}] - Prepare data to send", logId);
12    sessionIds.forEach(session::send);
13    log.debug("[{}] - All message are scheduled to send", logId);
14    // Thành công gửi thông báo tới các client
15    return true;
16}

Các thông tin liên quan tới trải nghiệm người dùng, hoặc thống kê cho mục đích kinh doanh.

Khi một chức năng tốn quá nhiều thời gian để xử lý hoặc thường xuyên lỗi chúng ta cũng cần ghi lại để tránh ảnh hưởng tới cảm nhận người dùng.

Các thông tin thống kê có thể sử dụng cho kinh doanh như số lượng giao dịch, đơn hàng trong ngày, số lượng người dùng online ... cũng có thể được ghi lại.

Thông tin liên quan khi thay đổi dữ liệu

Khi có các thay đổi dữ liệu (CRUD) chúng ta cần lưu thông tin nguồn tạo yêu cầu, có thể từ một người dùng hoặc từ một hệ thống khác. Các thông tin thường lưu như userName, serviceId, thời gian, hành vi (Thêm mới, sửa, xoá, đọc). Các trường dữ liệu sẽ bị thay đổi và nếu cần thiết có thể lưu cả thông tin bản ghi cũ và mới.

Thông tin liên quan tới perfomance

Ví dụ:

  • Số lần gọi API (Thành công và thất bại)
  • Tài nguyên sử dụng (CPU, Mem)
  • Thời gian xử lý trung bình
  • Tỷ lệ lỗi.

Các rủi ro và lỗ hổng bảo mật

Trước mình có được nghe anh thaidn(https://vnhacker.blogspot.com/) nói về việc làm bảo mật.

Việc xây dựng một ứng dụng bảo mật tốt giống xây một bức tường rào thật cao. Nhưng cao mấy rồi cũng có thể bị đột nhập. Vậy nên ngoài xây tường cao thì người ta còn có thêm các camera, cảm biến chuyển động ... để ngăn chặm xâm nhập.

Với ứng dụng bạn có thể ghi lại log các rủi ro tiềm tàng các hành động đáng ngờ của người dùng, cũng như các thay đổi bất thường của hệ thống.

Ví dụ:

Người dùng đăng nhập thất bại nhiều lần. Các thông tin có thể ghi lại như:

  • UserName
  • Địa chỉ IP người dùng
  • Số lần thất bại
  • Thời gian
  • Phân quyền của người dùng

Hệ thống có nhưng thông tin bất thường về:

  • Tài nguyên tiêu thụ
  • Thời gian xử lý
  • Số lượng lỗi

Tất các các thông tin trên được ghi lại có thể được sử dụng cho các hệ thống công cụ monitor để cảnh báo tới người giám sát.

3. Những dữ liệu không nên log hoặc phải ẩn thông tin trước khi ghi log.

Ẩn thông tin có thể thực hiện bằng cách:

  • Mask SDT: 0987654321 -> 098***321, Số tài khoản: A0003249230204 -> A00***0204
  • Xoá bỏ hoàn toàn không lưu vào log
  • Mã hoá

Tuỳ nghiệp vụ mà số lượng và vị trí ký tự được giữ lại có thể thay đổi.

Thông tin cá nhân người dùng.

  • Tên
  • Tuổi
  • Địa chỉ
  • Số điện thoại

Thông tin thanh toán

  • Số tài khoản
  • Số thẻ
  • Số dư

Các thông tin

  • Mật khẩu
  • Auth token
  • Private key
  • Secret key

4. Tổng kết

Ghi log phải có log id cho một luồng xử lý

12021-11-06T18:50:49+05:30 - INFO  -[fJLKjlkqjCLlqjwerlJKLZ] - GET /user/1
22021-11-06T18:50:49+05:30 - DEBUG -[fJLKjlkqjCLlqjwerlJKLZ] - [201.123.100.103] GET / HTTP/1.1 200 22.415µs Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36
32021-11-06T18:50:50+05:30 - ERROR -[fJLKjlkqjCLlqjwerlJKLZ] - [201.123.100.103] Can't connect to the database
42021-11-06T18:50:50+05:30 - INFO  -[fJLKjlkqjCLlqjwerlJKLZ] - [201.123.100.103] Can't get user info. Response to client { "code": 500, "message": "internal error"

Sử dụng đúng log level

Tài liệu tham khảo: https://reflectoring.io/logging-levels/

  • FATAL: Các lỗi có thể gây nên dừng ứng dụng. Thường ghi ra nguyên nhân lỗi trước khi ứng dụng bị dừng. Ví dụ: Tràn bộ nhớ.

  • ERROR: Thường được sử dụng khi các vấn đề liên quan tới business không thể thực hiện được do lý do về kỹ thuật và không thể khắc phục. Ví dụ: Lỗi xảy ra khi trừ tiền

    • Không thể trừ tiền do tài khoản không đủ hoặc tài khoản đích không tồn tại -> Đây không phải lỗi của ứng dụng.
    • Không thể trừ tiền do không kết nối được tới cơ sở dữ liệu -> Đây là lỗi.

Khi phát hiện log ERROR có thể developer sẽ phải sửa ngay để đảm bảo ứng dụng tiếp tục hoạt động chính xác. Vậy bạn không nên lạm dụng log error để tránh nhận được các cảnh báo không cần thiết. Trong Java một số Exception được bạn tạo ra và đã được xử lý ví dụ khi login không tìm thấy User bạn throw ra UserNotFoundException trường hợp này cần cân nhắc để không ghi log Error nếu không bạn sẽ nhận được cảnh báo lỗi thường xuyên.

  • WARN: Các cảnh báo cũng cần phải xem xét và xử lý nhưng độ ưu tiên thấp hơn ERROR. Các cảnh báo như tỷ lệ lỗi cao, lượng ram lớn hơn mức cấu hình (ví dụ: 70%). Hoặc với các lỗi kết nối nhưng có biện pháp khắc phục như thử lại(retry). Ví dụ: Không gửi được bản tin lên kafka bạn có thể gửi lại và ghi log WARN cho việc này, sau một số lần nhất định mà không thành công thì có thể đánh giá và ghi log ERROR.

  • INFO: Các bản tin, sự kiện quan trọng trong khi ứng dụng hoạt động.

  • DEBUG: Thường sử dụng để log lại chi tiết hơn các bước xử lý trong ứng dụng nhằm mục đích debug. Thông thường các log này sẽ sử dụng trên môi trường develop và test, đôi khi log debug cũng sẽ được sử dụng trong môi trường product trong giai đoạn đầu dự án hoặc khi có sự cố cần thêm thông tin và được tắt đi khi ứng dụng đã hoạt động ổn định.

Nên sử dụng tiếng Anh khi ghi log.

Đây là khuyến nghị chứ không bắt buộc, thường ngôn ngữ ghi log sẽ theo quy định công ty.

Ghi log ngắn gọn nhất có thể

Nếu ghi log quá dài có thể ảnh hưởng tới tốc độ ghi log, file log sẽ nặng hơn và có thể làm giảm thời gian có thể lưu trữ log. Vậy hãy cố gắng ghi log ngắn gọn và rõ nghĩa.

Ghi log source (Vị trí log được ghi trong code)

Khi đọc log có thể xác định được log ở hàm nào (Class, hàm, dòng nào ghi ra log này)

Không trùng các câu thông báo

Nhiều bạn hay copy các câu log dẫn tới bị nhầm hàm hoặc các log bị trùng như này.

12021-11-05 23:05:27 INFO - Request {some object}
22021-11-05 23:05:28 INFO - Response {some object}

Và copy cho tất cả mọi hàm. Nếu log source thì vẫn sẽ tra cứu được tuy nhiên theo ý kiến cá nhân mỗi hàm nên có log riêng đễ dễ tra cứu và từ log có thể lấy thông tin ngay mà không cần vào code.

12021-11-05 23:05:27 INFO - [000001] - UserController:23 - Create user with request {some object}
22021-11-05 23:05:28 INFO - [000001] - UserController:28 - Create user successfully. User info {some object}

12021-11-05 23:05:27 INFO - [000003] - UserController:23 - Update permission request {some object}
22021-11-05 23:05:28 ERROR - [000003] - UserController:28 - Update permission fail by blablabla

Ẩn các thông tin nhạy cảm

Như trong mục 3 đã nêu bạn có thể mã hoá, mask hoặc loại bỏ hoàn toàn thông tin nhạy cảm khỏi log.

Với log error cần ghi cụ thể

Ví dụ với log4j2 trong Java: Thay vì ghi

log.error("Fail to do something", ex.getMessage());

12021-11-05 23:05:28 ERROR - [000003] - UserController:28 - Fail to do something NullPointerException

Thì ta sẽ ghi đầy đủ stacktrace:

log.error("Fail to do something", ex);

12021-11-05 23:05:28 ERROR - [000003] - UserController:28 - Fail to do something java.lang.NullPointerException
2  at com.truongnq.product.library.ArgumentChecker.nonNull(ArgumentChecker.java:67)
3  at ...
4  at com.truongnq.product.aspects.CheckArgumentsAspect.wrap(CheckArgumentsAspect.java:82)
5  at ...
6  at com.truongq.product.MyTest.test(MyTest.java:37)

Cấu hình cho log

  • Bật level log nào
  • Dung lượng tối đa cho một file log, số file log tối đa lưu trữ ...
  • Một số bên để thuận tiện cho việc cảnh báo các file log Error sẽ được ghi riêng.