Best practices khi làm việc với logging trong Python

Logging là một yêu cầu không thể thiếu của mọi chương trình phần mềm khi sử dụng trong môi trường production. Với logging, các lập trình viên có thể truy cập được tình trạng của phần mềm. Đồng thời, sự phát triển của các dịch vụ đám mây về quản lý ứng dụng APM ( Application Performance Management) cũng giúp các lập trình viên có thể theo dõi logging để giám sát được hoạt động của phần mềm theo thời gian thực (real - time) và có thể đưa ra các hành động cần thiết nếu xảy ra lỗi. Do đó, một chương trình phần mềm có logging tốt sẽ giúp tăng năng suất hoạt động của phần mềm đó lên gấp nhiều lần.

Bài viết này sẽ trình bày những phương pháp tốt nhất khi làm việc với logging trong Python.

Python logging có 5 cấp độ từ thấp đến cao: Debug, Info, Warning, Error và Critical. Level mặc định của Python là Warning. Do đó, nếu chúng ta không đặt lại cấp độ log thì tất cả các message ở cấp độ Debug và Info sẽ không được log lại.

Ví dụ, chúng ta có một chương trình logging như bên dưới.

# logging_guide.py
import logging

logging.debug("This is a debug message")
logging.info("This is an informational message")
logging.warning("Careful! Something does not look right")
logging.error("You have encountered an error")
logging.critical("You are in trouble")

Kết quả của chương trình sẽ không hiển thị message với cấp độ log là debug và info.

 % python3 logging_guide.py
WARNING:root:Careful! Something does not look right
ERROR:root:You have encountered an error
CRITICAL:root:You are in trouble

Để có thể capture được tất cả các thông điệp log, ta sử dụng hàm basicconfig() trong module logging và gán level = 'DEBUG'

# logging_guide.py
import logging

logging.basicConfig(level='DEBUG')

logging.debug("This is a debug message")
logging.info("This is an informational message")
logging.warning("Careful! Something does not look right")
logging.error("You have encountered an error")
logging.critical("You are in trouble")

Kết quả:

% python3 logging_guide.py
DEBUG:root:This is a debug message
INFO:root:This is an informational message
WARNING:root:Careful! Something does not look right
ERROR:root:You have encountered an error
CRITICAL:root:You are in trouble

Module logging trong Python cung cấp các LogRecord attributes giúp chúng ta có thể lấy thêm thông tin từ log message.

Biến log_format ở trên cung cấp cho chúng ta những thông tin sau:
1) %(asctime)s : thời gian log được ghi lại.

2) %(levelname)s : cấp độ log trong số 5 cấp độ debug, info, warning, error, critical.

3) %(name)s : tên của logger được sử dụng để log message.

4) %(filename)s : tên chương trình chứa log.

5) %(message)s : nội dung message của log.

Chương trình:

# logging_guide.py
import logging

log_format = "%(asctime)s::%(levelname)s::%(name)s::"\
             "%(filename)s::%(lineno)d::%(message)s"
logging.basicConfig(level='DEBUG', format=log_format)

logging.debug("This is a debug message")
logging.info("This is an informational message")
logging.warning("Careful! Something does not look right")
logging.error("You have encountered an error")
logging.critical("You are in trouble")

Kết quả:

% python3 logging_guide.py
2021-05-16 14:28:02,878::DEBUG::root::logging_guide.py::8::This is a debug message
2021-05-16 14:28:02,878::INFO::root::logging_guide.py::9::This is an informational message
2021-05-16 14:28:02,878::WARNING::root::logging_guide.py::10::Careful! Something does not look right
2021-05-16 14:28:02,878::ERROR::root::logging_guide.py::11::You have encountered an error
2021-05-16 14:28:02,878::CRITICAL::root::logging_guide.py::12::You are in trouble

Với một chương trình trong môi trường production, chúng ta cần ghi lại nội dung của log trong một file text. Trong Python, điều này rất được hỗ trợ rất đơn giản thông qua câu lệnh filename trong basicconfig().

# logging_guide.py
import logging

log_format = "%(asctime)s::%(levelname)s::%(name)s::"\
             "%(filename)s::%(lineno)d::%(message)s"
logging.basicConfig(filename='mylogs.log', level='DEBUG', format=log_format)

logging.debug("This is a debug message")
logging.info("This is an informational message")
logging.warning("Careful! Something does not look right")
logging.error("You have encountered an error")
logging.critical("You are in trouble")

Sau khi chạy chương trình trên, chúng ta sẽ có được tất cả các log message trong một file tên là myLogs.log nằm trong cùng folder với file python.

Trong các project thực tế thì chúng ta gần như có nhiều hơn một file python trong working folder, và chúng ta cần phải log message cho từng file python khác nhau. Nếu chúng ta chỉ sử dụng basicconfig() thì sẽ có hiện tượng tất cả các file python đều dùng chung một logger là root. Điều này sẽ dẫn đến các log message bị chồng chéo khiến các messages không thể quản lý được.

Giả sử chúng ta có 2 file python là helper.py và project.py

File helper.py

# helper.py

import logging

logging.basicConfig(level='DEBUG')

logging.debug("I am a debug log from helper")

Và project.py trong đó chúng ta có import file helper.py 

# project.py

import logging
import helper

logging.basicConfig(level='DEBUG')

logging.debug("I am a debug log from project")

Nếu chạy file project.py, chúng ta mong muốn sẽ lấy được log message là DEBUG:root:I am a debug log from project

Tuy nhiên, kết quả sẽ hiển thị cả log message từ helper.py:

DEBUG:root:I am a debug log from helper
DEBUG:root:I am a debug log from project

Lý do là khi chúng ta import file helper.py, thì dòng log trong helper.py đã được thực thi trong logger root.

Cách tốt nhất là tạo mỗi logger riêng biệt cho từng file python như ví dụ bên dưới cho file project.py.

# project.py

import logging
import helper

log_format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
logger = logging.getLogger(__name__)

# To override the default severity of logging
logger.setLevel('DEBUG')

# Use FileHandler() to log to a file
file_handler = logging.FileHandler("mylogs.log")
formatter = logging.Formatter(log_format)
file_handler.setFormatter(formatter)

# Don't forget to add the file handler
logger.addHandler(file_handler)
logger.info("I am a log from project")

Kết quả là chúng ta sẽ nhận được log message trong file myLogs.log như bên dưới.

2021-05-16 15:03:01,653 - __main__ - INFO - I am a log from project

Thực hiện tương tự cho file helper.py, chúng ta có thể sử dụng hàm StreamHandler() để show log message trong terminal.

# helper.py

import logging

log_format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
logger = logging.getLogger(__name__)

# To override the default severity of logging
logger.setLevel('DEBUG')

# Use FileHandler() to log to a file
file_handler = logging.StreamHandler()
formatter = logging.Formatter(log_format)
file_handler.setFormatter(formatter)

# Don't forget to add the file handler
logger.addHandler(file_handler)
logger.info("I am a log from helper")

Trong bài này tôi đã giới thiệu một số best practices khi làm việc với logging trong Python bao gồm: thiết lập cấp độ cho log (bao gồm 5 cấp độ), sử dụng format để lấy thêm thông tin từ log message, và tạo từng logger riêng biệt khi làm việc trong một project có nhiều hơn một file python.

Hy vọng bài viết có thể giúp cho các bạn làm việc hiệu quả với Python logging.

A guide to run Python program inside a Docker container

A guide to deploy a Flask app to Heroku