Hướng dẫn python logger

Trong quá trình vận hành và sử dụng phần mềm, "phần mềm" cũng có lúc khỏe lúc yếu, lúc hoạt động trơn tru, lúc lại dặt dẹo. Vậy có những cách nào để "phần mềm" thông báo trạng thái hoạt động của mình với người dùng, IT-OPs, lập trình viên ?

Tại sao phải đặt log ?

Thông thường trong quá trình xây dựng và phát triển phần mềm, các lập trình viên sẽ đặt các đoạn lệnh try...except... tại các vị trí "nhạy cảm" có thể gây ra lỗi và bung lên màn hình các cảnh báo cho người dùng được biết về các lỗi xảy ra hoặc thông báo cho người dùng các vấn đề cần lưu ý (ví dụ như không được phép truy cập, cảnh báo về dữ liệu nhạy cảm, ...)
Việc bung ra các alert này phải được tính toán sao cho "friendly", dễ hiểu, hạn chế bung ra các lỗi của hệ thống mà chỉ có mấy ông dev mới hiểu được :))

Vậy thì muốn check lỗi của phần mềm thì IT-OPs/Dev phải làm thế nào ?

Nếu bạn mang câu hỏi này đi hỏi các lập trình viên có kinh nghiệm, câu trả lời dễ tìm thấy là "Ghi lỗi vào log file để có lỗi còn biết mà check & fix lỗi chứ" (Nhiều khi là đi "ăn vạ", "bắt đền" nếu lỗi phát sinh từ hệ thống khác).

Một số lập trình viên có thói quen đặt câu lệnh print ra màn hình console các thông tin trong quá trình ứng dụng chạy để "debug chay", trước khi release thì thực hiện "rào" (thực hiện chuyển command thành comment) hoặc xóa các dòng lệnh print này. Thật là mất thời gian và nếu có sai sót lại mất thêm cả thời gian để fix lỗi.

Log file có phải chỉ để ghi lỗi ?

Log file thường được ưu tiên để ghi vào các lỗi nhưng có những hệ thống đặc biệt, ngoài log lỗi thì log file còn có thể chứa các thông tin liên quan đến các action của người dùng vào hệ thống.
Ví dụ: Hệ thống fintech liên quan đến thanh toán giao dịch tiền, toàn bộ các action của người dùng trên phần mềm (hoặc web-app) đều cần phải ghi vào log:
- Khi người dùng đăng nhập vào --> Ghi log lại để có thể theo dõi thói quen của người dùng. Từ đó có thể trích xuất ra thông tin trong thời gian từ mấy giờ đến mấy giờ người dùng sẽ sử dụng ứng dụng nhiều.
- Khi thực hiện đặt lệnh thanh toán tiền --> Ghi log lại với thông tin của khác hàng + thông tin đích đến + thông tin số tiền để thực hiện đối soát dữ liệu mỗi ngày
....

Qua hai đầu mục trên, chúng ta đã thấy tầm quan trọng của log file, vậy đặt log như thế nào cho hiệu quả và dễ dàng khai thác thông tin sau này?

Ghi log thế nào cho hiệu quả?

1. Format log

Để việc sử dụng log đạt hiệu quả, trong mỗi team hoặc mỗi công ty cần có một chuẩn đặt log chúng để dễ dàng sử dụng sau khi thu thập log về chung một hệ thống lưu trữ.

Một cụm log nên chứa các thông tin sau:

• Datetime: thời gian ghi log, tính đến milisecond, định dạng nên dùng: yyyy-MM-dd HH:mm:ss,SSS. Ví dụ: 2020-09-17 09:50:55,901. Hoặc có thể sử dụng ISO local datetime (có thêm timezone)
• Log Level: Phân loại theo từng mục đích sử dụng, tuân theo quy định chung của từng công ty. Việc phân chia log-level sẽ giúp cho việc giám sát/bảo trì phần mềm thuận tiện hơn. Các log-level thường gặp: DEBUG, INFO, WARN, ERROR, CRITICAL/FATAL
• Tên component/module/function phát sinh ra log, nên đưa cả dòng phát sinh ra lỗi (nếu có thể phát hiện ra được trong cảnh báo lỗi)
• Log content: Nội dung lỗi muốn ghi vào file log.
• Request id: Id của session/phiên làm việc/request thực hiện các action để sinh ra log. Nếu có trường dữ liệu này, đến khi kiểm tra các event của session ở file log, chỉ cần thực hiện CTRL + F (nếu mở log file bằng editor) hoặc cat...| grep .... (nếu xem log từ màn hình terminal)
•  Parameter input: Thông tin dữ liệu đầu vào request đến.
•  Result output: Thông tin dữu liệu đầu ra do hệ thống trả về cho request đến

Ví dụ: Một kiểu format log như sau:
Datetime, Log Level, Component [code line] [Class/File name] [method/function...] Log Content [parameter input] [parameter output]

2020-09-22 20:05:12,636 INFO: [in ./app/api/report.py:341] [d20200922h2005id1001] create report success with account quangvinh2986 410421/200/Ok
2020-09-22 20:05:12,736 ERROR: [in ./app/api/report.py:345] [d20200922h2005id1001] download report 410421 fail

2. Chú ý phân loại log-level

Như đã viết ở trên, log-level được định nghĩa và sử dụng tùy mục đích sử dụng và phân loại của từng công ty. Dưới đây là một cách định nghĩa (mà các bạn có thể tham khảo):

DEBUG:
Log dùng để debug (rất nhiều và hỗn loạn). Mục đích sử dụng thường là dành cho developer.
Thông thường là đặt log level này enable trên môi trường LOCAL/DEVELOPING và disable ở PRODUCTION do số lượng dữ liệu log sẽ rất nhiều. Tuy nhiên đôi khi cũng phải enable lại level log này trên PRODUCTION để thực hiện ghi log và phát hiện ra các lỗi chỉ xảy ra trên PRODUCTION (Không phát sinh trên local).

Ví dụ: Hệ thống dữ liệu trên PRODUCTION thường lớn hơn nhiều so với DEVELOPING nên số lượng trường hợp xảy ra khi áp dữ liệu vào phần mềm cũng nhiều hơn. Các test-case có thể chưa bao quát được hết các lỗi --> Việc đặt debug có thể giúp developer/tester có thể giả lập lại được chính xác toàn bộ thao tác, workflow của cụm dữ liệu khi đi vào/đi ra khỏi phần mềm.

INFO:
Log mang tính chất cung cấp thông tin chung, không nên mang ý nghĩa chỉ định lỗi.
Ví dụ: Hành vi đăng nhâp vào hệ thống bởi tài khoản nào, version của phần mềm, ...

WARN (WARNING):
Log lại 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.
Ví dụ: Khách hàng cố tình nhấn nhiều lần vào button thanh toán trong khi người dùng không đủ điều kiện để thanh toán, các warning sẽ được log lại khi khách hàng "cố gắng" làm sai với hướng dẫn.

ERROR:
Log lại 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.

Ví dụ: Khách hàng thanh toán tiền cho dịch vụ A nhưng không thể trừ tiền của khách hàng do hệ thống thanh toán đang quá tải. Mỗi ERROR sẽ được ghi vào log-files để sau này có thể đối soát được lỗi quá tải đã gây ảnh hưởng đến bao nhiêu khách hàng.

FATAL/CRITICAL:
Log chỉ định để ghi các lỗi nghiêm trọng, thậm chí là đã gây ra gián đoạn dịch vụ, treo/crash phần mềm.

Ví dụ:
Phần mềm sử dụng nhiều, chiếm dụng RAM nhiều, gây tràn memory, phần mềm trước khi bị tự tắt đi sẽ đưa ra các thông báo.

Ghi chú: Với các case dạng này thì ngoài việc ghi vào log file thì nên thực hiện thông báo trực tiếp qua các kênh truyền thông với IT-Ops hoặc developer.

3. Thư viện hỗ trợ ghi log ?

Một lập trình viên, việc ghi log theo format như trên là một thử thách khá lớn về format chuỗi, format thời gian, ....
Hiểu được điều này các ngôn ngữ lập trình hiện đại sẽ có các module/library hỗ trợ việc ghi log cho đúng chuẩn và tiết kiệm thời gian, tài nguyên.
Ví dụ: Thư viện Log4j cho java, thư viện log4net cho .Net của Apache,...

Với ngôn ngữ lập trình Python, không cần phải cài đặt/thêm bớt library của hãng thứ 3 vào project của mình. Mọi thứ đã có sẵn trong module logging. Việc của lập trình viên chỉ là import vào sử dụng.

Đặt log với logging trong python

Ngôn ngữ lập trình Python cung cấp một module cho phép các lập trình viên thực hiện việc đặt log trong ứng dụng của mình là logging.
Sử dụng logging, lập trình viên sẽ được cung cấp các chức năng sau:

• Tạo ra các message bao gồm cả timestamp
• Sẵn có các loglevel: Info, Warning, Debug, Error.
• Có thể chọn đặt log lên màn hình console hoặc ghi ra file.
• Dễ dàng thực hiện on/off tiến trình đặt log.
• Phân chia file log thành nhiều đoạn theo dung lượng, theo thời gian.

Chúng ta sẽ cùng nhau khám phá về logging qua các ví dụ dưới đây nhé.

1. Đặt log, đưa dữ liệu vào màn hình console.

import logging

logging.basicConfig(format='%(asctime)s - %(levelname)s - %(message)s', level=logging.DEBUG)
logging.debug('This is a debug log message.')
logging.info('This is a info log message.')
logging.warning('This is a warning log message.')
logging.error('This is a error log message.')
logging.critical('This is a critical log message.')

Mặc định thì log sẽ được đẩy vào màn hình console, tất nhiên là màn hình console chỉ dành cho lập trình viên khi thực hiện debug nên các ứng dụng khi đưa lên PRODUCTION thì cần đặt log vào một log file

import logging

logging.basicConfig(filename='log_filename.log', format='%(asctime)s - %(levelname)s - %(message)s', level=logging.INFO)
logging.debug('This is a debug log message.')
logging.info('This is a info log message.')
logging.warning('This is a warning log message.')
logging.error('This is a error log message.')
logging.critical('This is a critical log message.')

Lưu ý:
Trường dữ liệu filename có thể là đường dẫn tuyệt đối hoặc tương đối đến vị trí đặt file.
Mỗi lần có thêm log, mặc định là log mới sẽ thêm tiếp vào cuối file log cũ.

Trường dữ liệu level sẽ thiết lập dữ liệu log nào được phép hiển thị theo từng cấp bậc.
Ví dụ ở trên chúng ta thiết lập level=logging.INFO, ở dòng lệnh bên dưới có logging.debug('This is a debug log message.') nhưng trong file log không xuất hiện dòng lệnh này do thứ tự "cấp bậc" của INFO lớn hơn DEBUG.

Thứ tự các level được mặc định như sau:
DEBUG --> INFO --> WARNING --> ERROR --> CRITICAL

Tại một phiên làm việc, logging chỉ nhận một giá trị level, muốn thay đổi log level, tùy chỉnh nhiều hơn, chúng ta nên sử dụng các đối tượng handlers của logging.

2. Đối tượng logging handlers

Các đối tượng logging handlers, chúng ta có thể tìm hiểu chúng ở đường dẫn sau: https://docs.python.org/3/library/logging.handlers.html

Để tìm hiểu về các đối tượng này, chúng ta sẽ đi đến ví dụ dưới đây

Các thông tin mới:
[in %(pathname)s:%(lineno)d]: sẽ cho ra đường dẫn đến file .py và dòng số bao nhiêu thực hiện ghi log
Formatter: Class cung cấp khả năng định dạng kiểu output của log.
FileHandler: Class thực hiện đưa log vào file đặt log.
StreamHandler: Class thực hiện đưa log ra màn hình console.

logger = logging.getLogger('mylog') --> Khởi tạo một đối tượng đại diện cho module logging trong module (file .py) hiện tại.

Đoạn script trên sẽ có output ra cả file và màn hình console. Theo như log-level thì trên file log sẽ in ra từ cụm INFO, trên màn hình console sẽ in ra cụm CRITICAL

Như đã nêu ở trên, trong phần log có thêm cụm thông tin tên file - dòng bao nhiêu [in .\handlers.py:26], có được đoạn dữ liệu này là do có đoạn cấu hình [in %(pathname)s:%(lineno)d] trong Formatter

3. Rotate log file.

Sau một quãng thời gian làm việc, file log lớn quá gây khó khăn cho việc đọc/ghi/theo dõi log. Logging module cung cấp việc thực hiện tách file log thành nhiều file khác nhau theo kích thước hoặc thời gian.

Thực hiện tách log file theo dung lượng.

import logging
from logging.handlers import RotatingFileHandler
from logging import Formatter

logger = logging.getLogger('RotatingFileHandler')
logger.setLevel(logging.DEBUG)

handler = RotatingFileHandler('log_filename.log', maxBytes=2000, backupCount=10)
formatter = Formatter('%(asctime)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)


logger.addHandler(handler)

for index in range(10000):
    logger.debug('This is a debug log message: {}'.format(index))
    logger.info('This is a info log message: {}'.format(index))
    logger.warning('This is a warning log message: {}'.format(index))
    logger.error('This is a error log message: {}'.format(index))
    logger.critical('This is a critical log message: {}'.format(index))

Sau khi thực thi, log file sẽ bung ra dưới dạng:

backupCount=10 --> lưu trữ backup tối đa thêm 10 file
maxBytes=2000 --> một file log có dung lượng tối đa 2000B, sau khi đạt dung lượng này, sẽ thực hiện rotate log sang dạng file backup, file ban đầu sẽ tiếp tục được ghi log vào.
Như ví dụ trên file log_filename.log sẽ chứa dữ liệu log mới nhất, log_filename.log.1 sẽ chứa dữ liệu log phía trước của log_filename.log.

Đoạn tiếp theo của log: 

Tách log file theo thời gian

import logging
from logging.handlers import TimedRotatingFileHandler
from logging import Formatter

formatter = Formatter('%(asctime)s - %(levelname)s - %(message)s')
logger = logging.getLogger('RotatingFileHandler')

# Split log at 0h everyday
handler = TimedRotatingFileHandler('time_log_file.log', when="midnight", interval=1)
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)

when trong TimedRotatingFileHandler có thể nhận các giá trị sau:
second (s)
minute (m)
hour (h)
day (d)
w0-w6 (weekday, 0=Monday)
midnight

Bật tắt logging.

Nếu không cần đến logging –> tắt chế độ ghi log:
logger.disabled = True

Khi cần bật lại:
logger.disabled = False

Kết luận

Trong nội dung bài viết này, tôi vừa trình bày với các bạn một số vấn đề liên quan đến tầm quan trọng việc ghi log trong xây dựng ứng dụng phần mềm. Đi kèm với phần lý thuyết là phần thực hành liên quan đến hướng dẫn sử dụng module logging trong ngôn ngữ lập trình Python.
Với các bạn đang sử dụng ngôn ngữ lập trình Java hoặc .NET các bạn có thể tìm hiểu cách sử dụng của 2 thư viện log4net và log4j để tự xây dựng cách chức năng ghi log theo ý của mình.
Cảm ơn các bạn đã đọc bài viết.