前言
本文的標題是『完整』。所謂『完整』，大意是想表達：提煉出一組最小的經驗組合，並且能夠快速應用於工程中，能 work，甚至能完美地 work。這篇文章就是想要做到『如何能完美地work』。
初衷
最原始的初衷就是：『現在的，是不完美的，不繫統的』。
一是：Python 官方對 logging 這個庫的使用，介紹得不夠“ 透徹 ”。我們能在官方文件中找到關於 logging 庫的有價值的東西，大概是如下幾樣：
- 庫文件，主要是介紹一些class，以及logging 庫是如何組成的，中間穿插了一些零碎的使用方法，但是仍然沒有系統介紹如何使用。它們分別是：
- 16.6. logging — Logging facility for Python
- 16.7. logging.config — Logging configuration
- 16.8. logging.handlers — Logging handlers
- 兩篇 HOWTOs。事無鉅細地介紹logging 這個庫的組成和使用，優點很明顯：事無鉅細，基本覆蓋到了。缺點也很明顯：事無鉅細，各個部分平均發力，讓人找不到重點，很容易迷失在其中，看了和沒看一樣。它們分別是：
- Logging HOWTO
- Logging Cookbook
二是：新手大概需要多年的經驗磨合，才會知道，日誌才是除錯最好的手段。日常開發中，單步除錯 VS 日誌除錯的比例大概是 1 ：9（我個人的是 0：10 ）。新手一般喜歡使用單步除錯，或是基於 print 的除錯，這兩者都是效率比較低下的，下面分別介紹：
- print除錯。不想介紹了，缺點比較多，我不說，大家也懂。適用於臨時性使用。
- 單步除錯。優點明顯：能單步，能看清每一步的狀況。缺點也很明顯：效率低，多執行緒情況下比較無解。適用於小範圍使用。
現在的情況
現在的情況，如同上面所說，大家沒有充分重視日誌除錯的作用，官方的logging庫亦是缺乏比較系統的『最小可用教程』。
HOW TO DO
先從需求出發，即：從呼叫端推導介面設計。
呼叫端大概率喜歡這麼使用（作為呼叫端，一般都希望介面越簡單越小越好）：
log_factory.SOME_LOGGER.info('MY LOG MSG')
複製程式碼這樣，我們可以把『log_factory』弄成一個 package（module也可以，不過我很喜歡 Go 語言那種看似麻煩實則規範的『基於package組織專案』的原則），『SOME_LOGGER』我們可以使用單例，不過Python有全域性變數這種東西，我們可以使用全域性變數。
另外，一個比較直覺的想法是：日誌應該要有對應的配置檔案，不過Python是指令碼語言，指令碼語言的原始碼檔案，天生就是配置檔案（因為指令碼語言一般不需要編譯，改改原始碼就能快速上線驗證，而且還可以熱更新）。
這樣，我們的目錄可以如此規劃：
common_libs/
__init__.py
log_factory/
__init__.py
程式碼可以直接寫在這裡，或者拆分成多個 py 檔案，反正對外也就提供一個『log_factory』的名稱空間
複製程式碼主要內容如下：
#!/usr/bin/env python
# -*- coding: utf-8 -*-
#
# author: he.zhiming
#
from __future__ import unicode_literals, absolute_import
import logging
import logging.config
import logging.handlers
from datetime import datetime
import os
class _InfoFilter(logging.Filter):
def filter(self, record):
"""only use INFO
篩選, 只需要 INFO 級別的log
:param record:
:return:
"""
if logging.INFO <= record.levelno < logging.ERROR:
# 已經是INFO級別了
# 然後利用父類, 返回 1
return super().filter(record)
else:
return 0
def _get_filename(*, basename='app.log', log_level='info'):
date_str = datetime.today().strftime('%Y%m%d')
pidstr = str(os.getpid())
return ''.join((
date_str, '-', pidstr, '-', log_level, '-', basename,))
class _LogFactory:
# 每個日誌檔案，使用 2GB
_SINGLE_FILE_MAX_BYTES = 2 * 1024 * 1024 * 1024
# 輪轉數量是 10 個
_BACKUP_COUNT = 10
# 基於 dictConfig，做再次封裝
_LOG_CONFIG_DICT = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
# 開發環境下的配置
'dev': {
'class': 'logging.Formatter',
'format': ('%(levelname)s %(asctime)s %(created)f %(name)s %(module)s [%(processName)s %(threadName)s] '
'[%(filename)s %(lineno)s %(funcName)s] %(message)s')
},
# 生產環境下的格式(越詳細越好)
'prod': {
'class': 'logging.Formatter',
'format': ('%(levelname)s %(asctime)s %(created)f %(name)s %(module)s %(process)d %(thread)d '
'%(filename)s %(lineno)s %(funcName)s %(message)s')
}
# ? 使用UTC時間!!!
},
# 針對 LogRecord 的篩選器
'filters': {
'info_filter': {
'()': _InfoFilter,
}
},
# 處理器(被loggers使用)
'handlers': {
'console': { # 按理來說, console只收集ERROR級別的較好
'class': 'logging.StreamHandler',
'level': 'ERROR',
'formatter': 'dev'
},
'file': {
'level': 'INFO',
'class': 'logging.handlers.RotatingFileHandler',
'filename': _get_filename(log_level='info'),
'maxBytes': _SINGLE_FILE_MAX_BYTES, # 2GB
'encoding': 'UTF-8',
'backupCount': _BACKUP_COUNT,
'formatter': 'dev',
'delay': True,
'filters': ['info_filter', ] # only INFO, no ERROR
},
'file_error': {
'level': 'ERROR',
'class': 'logging.handlers.RotatingFileHandler',
'filename': _get_filename(log_level='error'),
'maxBytes': _SINGLE_FILE_MAX_BYTES, # 2GB
'encoding': 'UTF-8',
'backupCount': _BACKUP_COUNT,
'formatter': 'dev',
'delay': True,
},
},
# 真正的logger(by name), 可以有豐富的配置
'loggers': {
'SAMPLE_LOGGER': {
# 輸送到3個handler，它們的作用分別如下
# 1. console：控制檯輸出，方便我們直接檢視，只記錄ERROR以上的日誌就好
# 2. file： 輸送到檔案，記錄INFO以上的日誌，方便日後回溯分析
# 3. file_error：輸送到檔案（與上面相同），但是隻記錄ERROR級別以上的日誌，方便研發人員排錯
'handlers': ['console', file', 'file_error'],
'level': 'INFO'
},
},
}
logging.config.dictConfig(_LOG_CONFIG_DICT)
@classmethod
def get_logger(cls, logger_name):
return logging.getLogger(logger_name)
# 一個示例
SAMPLE_LOGGER = _LogFactory.get_logger('SAMPLE_LOGGER')
# 示例——debugger，需要先配置好（如同SAMPLE_LOGGER一樣）
DEBUGGER = _LogFactory.get_logger('CONSOLE')
# 軟體專案一般是分層的，所以可以每一層放置一個logger，各司其職，這裡是一個示例
SOME_BASE_LIB_LOGGER = _LogFactory.get_logger('SOME_BASE_LIB_LOGGER')
複製程式碼幾個最佳實踐點
同一個logger配置多個handler
有個handler適合臨時排錯，有的handler適合永久記錄，有的handler記錄得事無鉅細，有的handler僅僅記錄關心的內容（如ERROR)
內容格式的設計
有如下幾點訴求：
- 能追蹤到程式、執行緒（必須要能追蹤到執行緒，多執行緒必備）
- 能追蹤到出錯行數
- 格式很規範統一
所以我們設計如下格式：
INFO 2018-05-18 16:42:56,637 1526632976.637384 DEBUGGER __main__ 73580 52688
__main__.py 29 test_func GOT RESULT. ['HELLO-WORLD FROM logginglib_project.business_layer.core.CoreUtils#get_hellowolrd']
分別對應
level date_time timestamp logger_name python_module process_id thread_id filename line_number function_name log_message
複製程式碼日誌檔名設定
比如 20180518-73580-info-debug_INFO.log，不用使用大腦思考，就知道是個什麼檔案
光說不練假把式
光說不練假把式，自己寫的程式碼，要『eat dog food』，演示如下：
更加高階的需求
INFO級別的handler，只使用『INFO <= && < ERROR』的日誌
利用logging庫提供的Filter概念，可以輕鬆實現：
先實現 Filter
class _InfoFilter(logging.Filter):
def filter(self, record):
"""only use INFO
篩選, 只需要 INFO 級別的log
:param record:
:return:
"""
if logging.INFO <= record.levelno < logging.ERROR:
# 已經是INFO級別了
# 然後利用父類, 返回 1
return super().filter(record)
else:
return 0
然後適配到Handler上面
'file': {
'level': 'INFO',
'class': 'logging.handlers.RotatingFileHandler',
'filename': _get_filename(log_level='info'),
'maxBytes': _SINGLE_FILE_MAX_BYTES, # 2GB
'encoding': 'UTF-8',
'backupCount': _BACKUP_COUNT,
'formatter': 'dev',
'delay': True,
'filters': ['info_filter', ] # only INFO, no ERROR
},
複製程式碼其他的注意事項
並不不一定適合框架（提供了完整日誌規範的），如Django
Django 提供的完整的日誌規範，一般的Django專案，按照框架的規範來即可（如Django，需要在settings檔案中配置 LOGGING)。
應該配置多少logger
一般按照自己的需求來，我有一個特別好的方式：按照軟體專案的分層結構來（軟體是分層的，應該是常識），每一層配置一個logger，這樣就不會混亂。
logging庫是程式安全，或者執行緒安全的嗎
是執行緒安全的，但不是程式安全的。但是可以很輕易地解決這點，即：每個檔名帶一個pid即可，讓每一個程式始終對應只屬於自己的檔案（見_get_filename的使用）。
固化我們的成果
變成 GitHub 上面的倉庫，歡迎 star。
連結：https://github.com/hezhiming/py_logging_usage/tree/master