Python 日志模块 logging
1. 简介 Python 日志记录模块
1.1 日志记录的重要性
- 部署到生产环境中的程序黑箱运行，无法通过调试程序来检查出现的问题，通过观察问题现象来调试，无法精准复现问题，修复问题棘手，会消耗大量时间
- 日志文件记录相关的时间记录，状态记录，错误记录等信息，方便地追踪运行状况，快速排查问题。
1.2 Logging模块优点
1.3 常用日志模块比较
图片摘自python输出日志
- print : 更加使用程序快速打印，不在乎日志格式，只想更快看到结果 ，一般用于程序的某个片段或者单点进行调试输出 。
- pprint: 对元组，列表，字典数据打印更加直观友好，若输出的是这种格式，可以优先考虑pprint .
- logging :对实现一个系统或框架时比较合适 ，且对日志需求有更高要求，可以优先考虑logging
- loguru ：对实现一个系统或框架也比较合适 ，但是更加轻量化，不需要配置 ，若对日志需求要求不高，可优先考虑loguru
2. Logging 模块组成和工作流
2.1 Logging 模块组成
- Logger：即 Logger Main Class，日志记录时创建的对象，我们可以调用Logger的方法传入日志模板和信息，来生成一条条日志记录，称作 Log Record。
- Log Record：就代指生成的一条条日志记录。
- Handler：处理日志记录的类，它可以将 Log Record 输出到指定的日志位置和存储形式等。
- Formatter：生成的 Log Record 也是对象，输出日志文本的话，就需要有一个格式化的过程，那么这个过程就由 Formatter 来完成，返回的就是日志字符串，然后传回给 Handler 来处理。
- Filter：保存前过滤，保存想要的日志，如只保存某个级别的日志，或只保存包含某个关键字的日志等，那么这个过滤过程就交给 Filter 来完成。
以上就是整个 logging 模块的基本架构和对象功能[3]，下面对Logging模块的对象及方法做简要的组成说明，详细参考[logging — Logging facility for Python]
2.1.1 Logging 模块类
>>> dir(logging.Logger)
['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', '_log', 'addFilter', 'addHandler', 'callHandlers', 'critical', 'debug', 'error', 'exception', 'fatal', 'filter', 'findCaller', 'getChild', 'getEffectiveLevel', 'handle', 'hasHandlers', 'info', 'isEnabledFor', 'log', 'makeRecord', 'manager', 'removeFilter', 'removeHandler', 'root', 'setLevel', 'warn', 'warning']
>>> dir(logging.Handler)
['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', 'acquire', 'addFilter', 'close', 'createLock', 'emit', 'filter', 'flush', 'format', 'get_name', 'handle', 'handleError', 'name', 'release', 'removeFilter', 'setFormatter', 'setLevel', 'set_name']
>>> dir(logging.Formatter)
['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', 'converter', 'default_msec_format', 'default_time_format', 'format', 'formatException', 'formatMessage', 'formatStack', 'formatTime', 'usesTime']
>>> dir(logging.Filter)
['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', 'filter']
2.1.2 Logging 模块层级函数
logging.getLogger(name=None)
logging.getLoggerClass()
logging.debug(msg, *args, **kwargs)
logging.info(msg, *args, **kwargs)
logging.warning(msg, *args, **kwargs)
logging.error(msg, *args, **kwargs)
logging.critical(msg, *args, **kwargs)
logging.exception(msg, *args, **kwargs)
logging.basicConfig(**kwargs)
Logging Level
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
| Level | When it’s used |
|---|---|
DEBUG |
Detailed information, typically of interest only when diagnosing problems. |
INFO |
Confirmation that things are working as expected. |
WARNING |
An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected. |
ERROR |
Due to a more serious problem, the software has not been able to perform some function. |
CRITICAL |
A serious error, indicating that the program itself may be unable to continue running. |
LogRecord attributes
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
| Attribute name | Format | Description |
|---|---|---|
| args | You shouldn’t need to format this yourself. | The tuple of arguments merged into msg to produce message, or a dict whose values are used for the merge (when there is only one argument, and it is a dictionary). |
| asctime | %(asctime)s |
Human-readable time when the LogRecord was created. By default this is of the form ‘2003-07-08 16:49:45,896’ (the numbers after the comma are millisecond portion of the time). |
| created | %(created)f |
Time when the LogRecord was created (as returned by time.time()). |
| exc_info | You shouldn’t need to format this yourself. | Exception tuple (à la sys.exc_info) or, if no exception has occurred, None. |
| filename | %(filename)s |
Filename portion of pathname. |
| funcName | %(funcName)s |
Name of function containing the logging call. |
| levelname | %(levelname)s |
Text logging level for the message ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'). |
| levelno | %(levelno)s |
Numeric logging level for the message (DEBUG, INFO, WARNING, ERROR, CRITICAL). |
| lineno | %(lineno)d |
Source line number where the logging call was issued (if available). |
| message | %(message)s |
The logged message, computed as msg % args. This is set when Formatter.format() is invoked. |
| module | %(module)s |
Module (name portion of filename). |
| msecs | %(msecs)d |
Millisecond portion of the time when the LogRecord was created. |
| msg | You shouldn’t need to format this yourself. | The format string passed in the original logging call. Merged with args to produce message, or an arbitrary object (see Using arbitrary objects as messages). |
| name | %(name)s |
Name of the logger used to log the call. |
| pathname | %(pathname)s |
Full pathname of the source file where the logging call was issued (if available). |
| process | %(process)d |
Process ID (if available). |
| processName | %(processName)s |
Process name (if available). |
| relativeCreated | %(relativeCreated)d |
Time in milliseconds when the LogRecord was created, relative to the time the logging module was loaded. |
| stack_info | You shouldn’t need to format this yourself. | Stack frame information (where available) from the bottom of the stack in the current thread, up to and including the stack frame of the logging call which resulted in the creation of this record. |
| thread | %(thread)d |
Thread ID (if available). |
| threadName | %(threadName)s |
Thread name (if available). |
2.2 Logging 工作流
2.3 Logging 配置工作流
配置 logging 有四种方法
方法1：logging.basicConfig()
"""
logging.basicConfig(
filename,
filemode,
format,
datefmt,
style,
level,
stream,
handlers
)
"""
import logging
_format = ('%(asctime)s '
'%(name)s ' # the name of logger
'%(levelname)s '
'%(filename)s '
'%(threadName)s '
'%(lineno)d: '
'%(message)s')
logging.basicConfig(
level=logging.DEBUG, # 默认 level 是 WARNING
filename='test.log',
format=_format,
)
logging.debug('logging debug')
logging.info('logging info')
方法2：直接 Python 代码调用配置方法
import logging
# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
# add formatter to ch
ch.setFormatter(formatter)
# add ch to logger
logger.addHandler(ch)
# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
方法3：创建配置文件，从文件中读取配置内容（fileConfig() ）
import logging
import logging.config
logging.config.fileConfig('logging.conf')
# create logger
logger = logging.getLogger('simpleExample')
# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
logging.conf (使用配置文件需去除批注)
[loggers]
keys=root,simpleExample
[handlers]
keys=consoleHandler
[formatters]
keys=simpleFormatter
##########################################################
[logger_root] # 定义 root 的日志器，logger_key1
level=DEBUG
handlers=consoleHandler # 继承自[handlers]中key
[logger_simpleExample] # 定义 simpleExample 的日志器,logger_key2
level=DEBUG
handlers=consoleHandler
qualname=simpleExample # 继承自[loggers]中key
propagate=0
[handler_consoleHandler] # 定义窗口输出的处理器,handlers_key1
class=StreamHandler
level=DEBUG
formatter=simpleFormatter # 继承自[formatters]中key
args=(sys.stdout,)
[formatter_simpleFormatter] # 定义格式器，formatters_key1
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
方法4：创建配置文件字典(YAML, JSON)，从字典中读取配置内容（dictConfig()）
def setup_logging(default_path = "config/logging.json", default_level = logging.INFO,env_key = "LOG_CFG"):
path = default_path
value = os.getenv(env_key,None)
if value:
path = value
if os.path.exists(path):
with open(path,"r") as f:
config = json.load(f)
logging.config.dictConfig(config)
else:
logging.basicConfig(level = default_level)
if __name__ == '__main__':
setup_logging(default_path = "config/logging.json")
main()
配置文件：YAML format dictionary
version: 1
formatters:
simple:
format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
console:
class: logging.StreamHandler
level: DEBUG
formatter: simple
stream: ext://sys.stdout
loggers:
simpleExample:
level: DEBUG
handlers: [console]
propagate: no
root:
level: DEBUG
handlers: [console]
配置文件：JSON format dictionary （去除#后内容方可使用）
{
"version":1,
"disable_existing_loggers":false,
"formatters":{
"simple":{
"format":"%(asctime)s - %(name)s - %(filename)s - %(funcName)s - %(lineno)d- %(levelname)s - %(message)s"
}
},
"handlers":{
"console":{
"class":"logging.StreamHandler",
"level":"DEBUG", # 设置 handlers 的输出级别，下一级
"formatter":"simple",
"stream":"ext://sys.stdout"
},
"info_file_handler":{
"class":"logging.handlers.RotatingFileHandler",
"level":"INFO", # 设置 handlers 的输出级别，下一级
"formatter":"simple",
"filename":"log/info.log",
"maxBytes":40960,
"backupCount":20,
"encoding":"utf8"
},
"error_file_handler":{
"class":"logging.handlers.RotatingFileHandler",
"level":"ERROR", # 设置 handlers 的输出级别，下一级
"formatter":"simple",
"filename":"log/errors.log",
"maxBytes":40960, # 单个文件大小 1024*40
"backupCount":20, #备份文件数目 20个文件
"encoding":"utf8"
}
},
"loggers":{
"my_module":{
"level":"ERROR", # 设置 Logger 的输出级别
"handlers":["info_file_handler"],
"propagate":"no"
}
},
"root":{
"level":"INFO",
"handlers":["console","info_file_handler","error_file_handler"]
}
}
2.4 简单的例子
import logging
import logging.handlers
logger = logging.getLogger('test')
logger.setLevel(level=logging.DEBUG) # 记录日志的级别
"""
%(name)s：Logger的名字
%(levelno)s：打印日志级别的数值
%(levelname)s：打印日志级别的名称
%(pathname)s：打印当前执行程序的路径，其实就是sys.argv[0]
%(filename)s：打印当前执行程序名
%(funcName)s：打印日志的当前函数
%(lineno)d：打印日志的当前行号
%(asctime)s：打印日志的时间
%(thread)d：打印线程ID
%(threadName)s：打印线程名称
%(process)d：打印进程ID
%(message)s：打印日志信息
"""
formatter = logging.Formatter('%(asctime)s - %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s')
"""
logging.StreamHandler -> 控制台输出
logging.FileHandler -> 文件输出
logging.handlers.RotatingFileHandler -> 按照大小自动分割日志文件，一旦达到指定的大小重新生成文件
logging.handlers.TimedRotatingFileHandler -> 按照时间自动分割日志文件
"""
file_handler = logging.FileHandler('log/test.log') # 输出文件日志的位置方式，添加文件位置
file_handler.setLevel(level=logging.INFO) # 输出文件日志的级别
file_handler.setFormatter(formatter) # 输出文件日志的格式
stream_handler = logging.StreamHandler() # 输出屏幕日志的位置方式
stream_handler.setLevel(logging.DEBUG) # 输出屏幕日志的级别
stream_handler.setFormatter(formatter) # 输出屏幕日志的格式
# time_rotating_file_handler = logging.handlers.TimedRotatingFileHandler(filename='rotating_test.log', when='D')
# time_rotating_file_handler.setLevel(logging.DEBUG)
# time_rotating_file_handler.setFormatter(formatter)
logger.addHandler(file_handler)
logger.addHandler(stream_handler)
# logger.addHandler(time_rotating_file_handler)
# 运行测试
logger.debug('debug级别，一般用来打印一些调试信息，级别最低')
logger.info('info级别，一般用来打印一些正常的操作信息')
logger.warning('waring级别，一般用来打印警告信息')
logger.error('error级别，一般用来打印一些错误信息')
logger.critical('critical级别，一般用来打印一些致命的错误信息，等级最高')
3. Logging 模块用法
3.1 日志写入到文件和屏幕
输出到文件：设置logging，创建一个FileHandler，并对输出消息的格式进行设置，将其添加到logger，然后将日志写入到指定的文件中
输出到屏幕： logger中添加StreamHandler，可以将日志输出到屏幕上
其他不同的 Handler 方式
StreamHandler：logging.StreamHandler；日志输出到流，可以是sys.stderr，sys.stdout或者文件
FileHandler：logging.FileHandler；日志输出到文件
BaseRotatingHandler：logging.handlers.BaseRotatingHandler；基本的日志回滚方式
RotatingHandler：logging.handlers.RotatingHandler；日志回滚方式，支持日志文件最大数量和日志文件回滚
TimeRotatingHandler：logging.handlers.TimeRotatingHandler；日志回滚方式，在一定时间区域内回滚日志文件
SocketHandler：logging.handlers.SocketHandler；远程输出日志到TCP/IP sockets
DatagramHandler：logging.handlers.DatagramHandler；远程输出日志到UDP sockets
SMTPHandler：logging.handlers.SMTPHandler；远程输出日志到邮件地址
SysLogHandler：logging.handlers.SysLogHandler；日志输出到syslog
NTEventLogHandler：logging.handlers.NTEventLogHandler；远程输出日志到Windows NT/2000/XP的事件日志
MemoryHandler：logging.handlers.MemoryHandler；日志输出到内存中的指定buffer
HTTPHandler：logging.handlers.HTTPHandler；通过"GET"或者"POST"远程输出到HTTP服务器
同时输出达到屏幕和文件可参考下一节。
3.2 多模块输出（Logging from multiple modules）
例子1： 最简单例子解释使用模式
# myapp.py
import logging
import mylib
def main():
logging.basicConfig(filename='myapp.log', level=logging.INFO)
logging.info('Started')
mylib.do_something()
logging.info('Finished')
if __name__ == '__main__':
main()
# mylib.py
import logging
def do_something():
logging.info('Doing something')
输出
>>>
INFO:root:Started
INFO:root:Doing something
INFO:root:Finished
例子2： 多模块追踪信息来源[4]
# mainModule.py
import logging
import subModule
logger = logging.getLogger("mainModule") # 主模块定义了logger'mainModule'，在python解释器进程其他模块里都可以使用logger对象，不需要反复的定义和配置各个模块的logger
logger.setLevel(level = logging.INFO)
handler = logging.FileHandler("log.txt")
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
console = logging.StreamHandler()
console.setLevel(logging.INFO)
console.setFormatter(formatter)
logger.addHandler(handler)
logger.addHandler(console)
logger.info("creating an instance of subModule.subModuleClass")
a = subModule.SubModuleClass()
logger.info("calling subModule.subModuleClass.doSomething")
a.doSomething()
logger.info("done with subModule.subModuleClass.doSomething")
logger.info("calling subModule.some_function")
subModule.som_function()
logger.info("done with subModule.some_function")
import logging
module_logger = logging.getLogger("mainModule.sub") # 任意以'mainModule'开头的logger都是它的子logger
class SubModuleClass(object):
def __init__(self):
self.logger = logging.getLogger("mainModule.sub.module")
self.logger.info("creating an instance in SubModuleClass")
def doSomething(self):
self.logger.info("do something in SubModule")
a = []
a.append(1)
self.logger.debug("list a = " + str(a))
self.logger.info("finish something in SubModuleClass")
def som_function():
module_logger.info("call function some_function")
输出
>>>
2016-10-09 20:25:42,276 - mainModule - INFO - creating an instance of subModule.subModuleClass
2016-10-09 20:25:42,279 - mainModule.sub.module - INFO - creating an instance in SubModuleClass
2016-10-09 20:25:42,279 - mainModule - INFO - calling subModule.subModuleClass.doSomething
2016-10-09 20:25:42,279 - mainModule.sub.module - INFO - do something in SubModule
2016-10-09 20:25:42,279 - mainModule.sub.module - INFO - finish something in SubModuleClass
2016-10-09 20:25:42,279 - mainModule - INFO - done with subModule.subModuleClass.doSomething
2016-10-09 20:25:42,279 - mainModule - INFO - calling subModule.some_function
2016-10-09 20:25:42,279 - mainModule.sub - INFO - call function some_function
2016-10-09 20:25:42,279 - mainModule - INFO - done with subModule.some_function
3.3 Logging 记录 Traceback 信息
Python中的traceback模块被用于跟踪异常返回信息，可以在logging中记录下traceback.改部分摘自参考文章[3:1]。
import logging
logger = logging.getLogger(__name__)
logger.setLevel(level = logging.INFO)
handler = logging.FileHandler("log.txt")
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
console = logging.StreamHandler()
console.setLevel(logging.INFO)
logger.addHandler(handler)
logger.addHandler(console)
logger.info("Start print log")
logger.debug("Do something")
logger.warning("Something maybe fail.")
try:
open("sklearn.txt","rb")
except (SystemExit,KeyboardInterrupt):
raise
except Exception:
logger.error("Faild to open sklearn.txt from logger.error",exc_info = True) # 方法1
logger.exception("Failed to open sklearn.txt from logger.exception") # 方法2
logger.info("Finish")
Start print log
Something maybe fail.
Faild to open sklearn.txt from logger.error
Traceback (most recent call last):
File "G:\zhb7627\Code\Eclipse WorkSpace\PythonTest\test.py", line 23, in <module>
open("sklearn.txt","rb")
IOError: [Errno 2] No such file or directory: 'sklearn.txt'
Finish
3.4 输出进度信息
logging.info("Operating progress: {:.1f}%, {} ".format(num/cycle_No*100, ">" * (num // 2)))
