python模块学习 -- 日志logging

1 logging模块简介

logging模块是Python内置的标准模块,主要用于输出运行日志,可以设置输出日志的等级、日志保存路径、日志文件回滚等;相比print,具备如下优点:

  1. 可以通过设置不同的日志等级,在release版本中只输出重要信息,而不必显示大量的调试信息;
  2. print将所有信息都输出到标准输出中,严重影响开发者从标准输出中查看其它数据;logging则可以由开发者决定将信息输出到什么地方,以及怎么输出;

 

在开发过程中,如果程序运行出现了问题,我们是可以使用我们自己的 Debug 工具来检测到到底是哪一步出现了问题,如果出现了问题的话,是很容易排查的。但程序开发完成之后,我们会将它部署到生产环境中去,这时候代码相当于是在一个黑盒环境下运行的,我们只能看到其运行的效果,是不能直接看到代码运行过程中每一步的状态的。在这个环境下,运行过程中难免会在某个地方出现问题,甚至这个问题可能是我们开发过程中未曾遇到的问题,碰到这种情况应该怎么办?

如果我们现在只能得知当前问题的现象,而没有其他任何信息的话,如果我们想要解决掉这个问题的话,那么只能根据问题的现象来试图复现一下,然后再一步步去调试,这恐怕是很难的,很大的概率上我们是无法精准地复现这个问题的,而且 Debug 的过程也会耗费巨多的时间,这样一旦生产环境上出现了问题,修复就会变得非常棘手。但这如果我们当时有做日志记录的话,不论是正常运行还是出现报错,都有相关的时间记录,状态记录,错误记录等,那么这样我们就可以方便地追踪到在当时的运行过程中出现了怎样的状况,从而可以快速排查问题。

因此,日志记录是非常有必要的,任何一款软件如果没有标准的日志记录,都不能算作一个合格的软件。作为开发者,我们需要重视并做好日志记录过程。

python模块学习 -- 日志logging

如图所示,整个日志记录的框架可以分为这么几个部分:

  • Logger:即 Logger Main Class,是我们进行日志记录时创建的对象,我们可以调用它的方法传入日志模板和信息,来生成一条条日志记录,称作 Log Record。
  • Log Record:就代指生成的一条条日志记录。
  • Handler:即用来处理日志记录的类,它可以将 Log Record 输出到我们指定的日志位置和存储形式等,如我们可以指定将日志通过 FTP 协议记录到远程的服务器上,Handler 就会帮我们完成这些事情。
  • Formatter:实际上生成的 Log Record 也是一个个对象,那么我们想要把它们保存成一条条我们想要的日志文本的话,就需要有一个格式化的过程,那么这个过程就由 Formatter 来完成,返回的就是日志字符串,然后传回给 Handler 来处理。
  • Filter:另外保存日志的时候我们可能不需要全部保存,我们可能只需要保存我们想要的部分就可以了,所以保存前还需要进行一下过滤,留下我们想要的日志,如只保存某个级别的日志,或只保存包含某个关键字的日志等,那么这个过滤过程就交给 Filter 来完成。
  • Parent Handler:Handler 之间可以存在分层关系,以使得不同 Handler 之间共享相同功能的代码。

以上就是整个 logging 模块的基本架构和对象功能,了解了之后我们详细来了解一下 logging 模块的用法。

2 logging模块使用

2.1 基本使用

配置logging基本的设置,然后在控制台输出日志,

import logging
logging.basicConfig(level = logging.INFO,format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info("Start print log")
logger.debug("Do something")
logger.warning("Something maybe fail.")
logger.info("Finish")

运行时,控制台输出,

2016-10-09 19:11:19,434 - __main__ - INFO - Start print log
2016-10-09 19:11:19,434 - __main__ - WARNING - Something maybe fail.
2016-10-09 19:11:19,434 - __main__ - INFO - Finish

logging中可以选择很多消息级别,如debug、info、warning、error以及critical。通过赋予logger或者handler不同的级别,开发者就可以只输出错误信息到特定的记录文件,或者在调试时只记录调试信息。

例如,我们将logger的级别改为DEBUG,再观察一下输出结果,

logging.basicConfig(level = logging.DEBUG,format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s')

控制台输出,可以发现,输出了debug的信息。

2016-10-09 19:12:08,289 - __main__ - INFO - Start print log
2016-10-09 19:12:08,289 - __main__ - DEBUG - Do something
2016-10-09 19:12:08,289 - __main__ - WARNING - Something maybe fail.
2016-10-09 19:12:08,289 - __main__ - INFO - Finish

logging.basicConfig函数各参数:

filename:指定日志文件名;

filemode:和file函数意义相同,指定日志文件的打开模式,'w'或者'a';

format:指定输出的格式和内容,format可以输出很多有用的信息,

参数:作用

%(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:打印日志信息
  1. datefmt:指定时间格式,同time.strftime();
  2. level:设置日志级别,默认为logging.WARNNING;
  3. stream:指定将日志的输出流,可以指定输出到sys.stderr,sys.stdout或者文件,默认输出到sys.stderr,当stream和filename同时指定时,stream被忽略;

level:

等级 数值
CRITICAL 50
FATAL 50
ERROR 40
WARNING 30
WARN 30
INFO 20
DEBUG 10
NOTSET 0
日志等级:使用范围

FATAL:致命错误
CRITICAL:特别糟糕的事情,如内存耗尽、磁盘空间为空,一般很少使用
ERROR:发生错误时,如IO操作失败或者连接问题
WARNING:发生很重要的事件,但是并不是错误时,如用户登录密码错误
INFO:处理请求或者状态变化等日常事务
DEBUG:调试过程中使用DEBUG等级,如算法中每个循环的中间状态

这里最高的等级是 CRITICAL 和 FATAL,两个对应的数值都是 50,另外对于 WARNING 还提供了简写形式 WARN,两个对应的数值都是 30。

我们设置了输出 level,系统便只会输出 level 数值大于或等于该 level 的的日志结果,例如我们设置了输出日志 level 为 INFO,那么输出级别大于等于 INFO 的日志,如 WARNING、ERROR 等,DEBUG 和 NOSET 级别的不会输出。

2.2 Handler

下面我们先来了解一下 Handler 的用法,看下面的实例:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
handler = logging.FileHandler('output.log')
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

这里我们没有再使用 basicConfig 全局配置,而是先声明了一个 Logger 对象,然后指定了其对应的 Handler 为 FileHandler 对象,然后 Handler 对象还单独指定了 Formatter 对象单独配置输出格式,最后给 Logger 对象添加对应的 Handler 即可,最后可以发现日志就会被输出到 output.log 中,内容如下:

2018-06-03 14:53:36,467 - __main__ - INFO - This is a log info
2018-06-03 14:53:36,468 - __main__ - WARNING - Warning exists
2018-06-03 14:53:36,468 - __main__ - INFO - Finish

另外我们还可以使用其他的 Handler 进行日志的输出,logging 模块提供的 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服务器。

下面我们使用三个 Handler 来实现日志同时输出到控制台、文件、HTTP 服务器:

import logging
from logging.handlers import HTTPHandler
import sys

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.DEBUG)

# StreamHandler
stream_handler = logging.StreamHandler(sys.stdout)
stream_handler.setLevel(level=logging.DEBUG)
logger.addHandler(stream_handler)

# FileHandler
file_handler = logging.FileHandler('output.log')
file_handler.setLevel(level=logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# HTTPHandler
http_handler = HTTPHandler(host='localhost:8001', url='log', method='POST')
logger.addHandler(http_handler)

# Log
logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

运行之前我们需要先启动 HTTP Server,并运行在 8001 端口,其中 log 接口是用来接收日志的接口。

运行之后控制台输出会输出如下内容:

This is a log info
Debugging
Warning exists
Finish

output.log 文件会写入如下内容:

2018-06-03 15:13:44,895 - __main__ - INFO - This is a log info
2018-06-03 15:13:44,947 - __main__ - WARNING - Warning exists
2018-06-03 15:13:44,949 - __main__ - INFO - Finish

HTTP Server 会收到控制台输出的信息。

这样一来,我们就通过设置多个 Handler 来控制了日志的多目标输出。

另外值得注意的是,在这里 StreamHandler 对象我们没有设置 Formatter,因此控制台只输出了日志的内容,而没有包含时间、模块等信息,而 FileHandler 我们通过 setFormatter() 方法设置了一个 Formatter 对象,因此输出的内容便是格式化后的日志信息。

另外每个 Handler 还可以设置 level 信息,最终输出结果的 level 信息会取 Logger 对象的 level 和 Handler 对象的 level 的交集。

2.3 Formatter

在进行日志格式化输出的时候,我们可以不借助于 basicConfig 来全局配置格式化输出内容,可以借助于 Formatter 来完成,下面我们再来单独看下 Formatter 的用法:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.WARN)
formatter = logging.Formatter(fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s', datefmt='%Y/%m/%d %H:%M:%S')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)

# Log
logger.debug('Debugging')
logger.critical('Critical Something')
logger.error('Error Occurred')
logger.warning('Warning exists')
logger.info('Finished')

在这里我们指定了一个 Formatter,并传入了 fmt 和 datefmt 参数,这样就指定了日志结果的输出格式和时间格式,然后 handler 通过 setFormatter() 方法设置此 Formatter 对象即可,输出结果如下:

2018/06/03 15:47:15 - __main__ - CRITICAL - Critical Something
2018/06/03 15:47:15 - __main__ - ERROR - Error Occurred
2018/06/03 15:47:15 - __main__ - WARNING - Warning exists

这样我们可以每个 Handler 单独配置输出的格式,非常灵活。

2.4 配置共享

在写项目的时候,我们肯定会将许多配置放置在许多模块下面,这时如果我们每个文件都来配置 logging 配置那就太繁琐了,logging 模块提供了父子模块共享配置的机制,会根据 Logger 的名称来自动加载父模块的配置。

例如我们这里首先定义一个 main.py 文件:

import logging
import core

logger = logging.getLogger('main')
logger.setLevel(level=logging.DEBUG)

# Handler
handler = logging.FileHandler('result.log')
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('Main Info')
logger.debug('Main Debug')
logger.error('Main Error')
core.run()

这里我们配置了日志的输出格式和文件路径,同时定义了 Logger 的名称为 main,然后引入了另外一个模块 core,最后调用了 core 的 run() 方法。

接下来我们定义 core.py,内容如下:

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')

这里我们定义了 Logger 的名称为 main.core,注意这里开头是 main,即刚才我们在 main.py 里面的 Logger 的名称,这样 core.py 里面的 Logger 就会复用 main.py 里面的 Logger 配置,而不用再去配置一次了。

运行之后会生成一个 result.log 文件,内容如下:

2018-06-03 16:55:56,259 - main - INFO - Main Info
2018-06-03 16:55:56,259 - main - ERROR - Main Error
2018-06-03 16:55:56,259 - main.core - INFO - Core Info
2018-06-03 16:55:56,259 - main.core - ERROR - Core Error

可以看到父子模块都使用了同样的输出配置。

如此一来,我们只要在入口文件里面定义好 logging 模块的输出配置,子模块只需要在定义 Logger 对象时名称使用父模块的名称开头即可共享配置,非常方便。

2.5 文件配置

在开发过程中,将配置在代码里面写死并不是一个好的习惯,更好的做法是将配置写在配置文件里面,我们可以将配置写入到配置文件,然后运行时读取配置文件里面的配置,这样是更方便管理和维护的,下面我们以一个实例来说明一下,首先我们定义一个 yaml 配置文件:

version: 1
formatters:
  brief:
    format: "%(asctime)s - %(message)s"
  simple:
    format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
handlers:
  console:
    class : logging.StreamHandler
    formatter: brief
    level   : INFO
    stream  : ext://sys.stdout
  file:
    class : logging.FileHandler
    formatter: simple
    level: DEBUG
    filename: debug.log
  error:
    class: logging.handlers.RotatingFileHandler
    level: ERROR
    formatter: simple
    filename: error.log
    maxBytes: 10485760
    backupCount: 20
    encoding: utf8
loggers:
  main.core:
    level: DEBUG
    handlers: [console, file, error]
root:
  level: DEBUG
  handlers: [console]

这里我们定义了 formatters、handlers、loggers、root 等模块,实际上对应的就是各个 Formatter、Handler、Logger 的配置,参数和它们的构造方法都是相同的。

接下来我们定义一个主入口文件,main.py,内容如下:

import logging
import core
import yaml
import logging.config
import os


def setup_logging(default_path='config.yaml', default_level=logging.INFO):
    path = default_path
    if os.path.exists(path):
        with open(path, 'r', encoding='utf-8') as f:
            config = yaml.load(f)
            logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)


def log():
    logging.debug('Start')
    logging.info('Exec')
    logging.info('Finished')


if __name__ == '__main__':
    yaml_path = 'config.yaml'
    setup_logging(yaml_path)
    log()
    core.run()

这里我们定义了一个 setup_logging() 方法,里面读取了 yaml 文件的配置,然后通过 dictConfig() 方法将配置项传给了 logging 模块进行全局初始化。

另外这个模块还引入了另外一个模块 core,所以我们定义 core.py 如下:

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')

这个文件的内容和上文是没有什么变化的。

观察配置文件,主入口文件 main.py 实际上对应的是 root 一项配置,它指定了 handlers 是 console,即只输出到控制台。另外在 loggers 一项配置里面,我们定义了 main.core 模块,handlers 是 console、file、error 三项,即输出到控制台、输出到普通文件和回滚文件。

这样运行之后,我们便可以看到所有的运行结果输出到了控制台:

2018-06-03 17:07:12,727 - Exec
2018-06-03 17:07:12,727 - Finished
2018-06-03 17:07:12,727 - Core Info
2018-06-03 17:07:12,727 - Core Info
2018-06-03 17:07:12,728 - Core Error
2018-06-03 17:07:12,728 - Core Error

在 debug.log 文件中则包含了 core.py 的运行结果:

2018-06-03 17:07:12,727 - main.core - INFO - Core Info
2018-06-03 17:07:12,727 - main.core - DEBUG - Core Debug
2018-06-03 17:07:12,728 - main.core - ERROR - Core Error

可以看到,通过配置文件,我们可以非常灵活地定义 Handler、Formatter、Logger 等配置,同时也显得非常直观,也非常容易维护,在实际项目中,推荐使用此种方式进行配置。

以上便是 logging 模块的基本使用方法,有了它,我们可以方便地进行日志管理和维护,会给我们的工作带来极大的方便。

2.6 日志记录使用常见误区

在日志输出的时候经常我们会用到字符串拼接的形式,很多情况下我们可能会使用字符串的 format() 来构造一个字符串,但这其实并不是一个好的方法,因为还有更好的方法,下面我们对比两个例子:

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# bad
logging.debug('Hello {0}, {1}!'.format('World', 'Congratulations'))
# good
logging.debug('Hello %s, %s!', 'World', 'Congratulations')

这里有两种打印 Log 的方法,第一种使用了字符串的 format() 的方法进行构造,传给 logging 的只用到了第一个参数,实际上 logging 模块提供了字符串格式化的方法,我们只需要在第一个参数写上要打印输出的模板,占位符用 %s、%d 等表示即可,然后在后续参数添加对应的值就可以了,推荐使用这种方法。

运行结果如下:

2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!
2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!

 

python模块学习 -- 日志logging

 

另外在进行异常处理的时候,通常我们会直接将异常进行字符串格式化,但其实可以直接指定一个参数将 traceback 打印出来,示例如下:

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

try:
    result = 5 / 0
except Exception as e:
    # bad
    logging.error('Error: %s', e)
    # good
    logging.error('Error', exc_info=True)
    # good
    logging.exception('Error')

如果我们直接使用字符串格式化的方法将错误输出的话,是不会包含 Traceback 信息的,但如果我们加上 exc_info 参数或者直接使用 exception() 方法打印的话,那就会输出 Traceback 信息了。

运行结果如下:

2018-06-03 22:24:31,927 - root - ERROR - Error: division by zero
2018-06-03 22:24:31,927 - root - ERROR - Error
Traceback (most recent call last):
  File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero
2018-06-03 22:24:31,928 - root - ERROR - Error
Traceback (most recent call last):
  File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero

 

python模块学习 -- 日志logging

 

 

2.7 将日志写入到文件

设置logging,创建一个FileHandler,并对输出消息的格式进行设置,将其添加到logger,然后将日志写入到指定的文件中,

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)
logger.addHandler(handler)

logger.info("Start print log")
logger.debug("Do something")
logger.warning("Something maybe fail.")
logger.info("Finish")

log.txt中日志数据为,

2016-10-09 19:01:13,263 - __main__ - INFO - Start print log
2016-10-09 19:01:13,263 - __main__ - WARNING - Something maybe fail.
2016-10-09 19:01:13,263 - __main__ - INFO - Finish

2.8 将日志同时输出到屏幕和日志文件

logger中添加StreamHandler,可以将日志输出到屏幕上,

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.")
logger.info("Finish")

可以在log.txt文件和控制台中看到,

2016-10-09 19:20:46,553 - __main__ - INFO - Start print log
2016-10-09 19:20:46,553 - __main__ - WARNING - Something maybe fail.
2016-10-09 19:20:46,553 - __main__ - INFO - Finish

可以发现,logging有一个日志处理的主对象,其他处理方式都是通过addHandler添加进去,logging中包含的handler主要有如下几种,

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服务器

2.9日志回滚

使用RotatingFileHandler,可以实现日志回滚,

import logging
from logging.handlers import RotatingFileHandler
logger = logging.getLogger(__name__)
logger.setLevel(level = logging.INFO)
#定义一个RotatingFileHandler,最多备份3个日志文件,每个日志文件最大1K
rHandler = RotatingFileHandler("log.txt",maxBytes = 1*1024,backupCount = 3)
rHandler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
rHandler.setFormatter(formatter)

console = logging.StreamHandler()
console.setLevel(logging.INFO)
console.setFormatter(formatter)

logger.addHandler(rHandler)
logger.addHandler(console)

logger.info("Start print log")
logger.debug("Do something")
logger.warning("Something maybe fail.")
logger.info("Finish")

可以在工程目录中看到,备份的日志文件,

2016/10/09  19:36               732 log.txt
2016/10/09  19:36               967 log.txt.1
2016/10/09  19:36               985 log.txt.2
2016/10/09  19:36               976 log.txt.3

 

3.0 捕获traceback

Python中的traceback模块被用于跟踪异常返回信息,可以在logging中记录下traceback,

代码,

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)

logger.info("Finish")

控制台和日志文件log.txt中输出,

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

也可以使用logger.exception(msg,_args),它等价于logger.error(msg,exc_info = True,_args),

logger.error("Faild to open sklearn.txt from logger.error",exc_info = True)

替换为,

logger.exception("Failed to open sklearn.txt from logger.exception")

控制台和日志文件log.txt中输出,

Start print log
Something maybe fail.
Failed to open sklearn.txt from logger.exception
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.1  多模块使用logging

主模块mainModule.py,

import logging
import subModule
logger = logging.getLogger("mainModule")
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")

子模块subModule.py,

import logging

module_logger = logging.getLogger("mainModule.sub")
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")

执行之后,在控制和日志文件log.txt中输出,

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

首先在主模块定义了logger'mainModule',并对它进行了配置,就可以在解释器进程里面的其他地方通过getLogger('mainModule')得到的对象都是一样的,不需要重新配置,可以直接使用。定义的该logger的子logger,都可以共享父logger的定义和配置,所谓的父子logger是通过命名来识别,任意以'mainModule'开头的logger都是它的子logger,例如'mainModule.sub'。

实际开发一个application,首先可以通过logging配置文件编写好这个application所对应的配置,可以生成一个根logger,如'PythonAPP',然后在主函数中通过fileConfig加载logging配置,接着在application的其他地方、不同的模块中,可以使用根logger的子logger,如'PythonAPP.Core','PythonAPP.Web'来进行log,而不需要反复的定义和配置各个模块的logger。

3.2  通过logging.config模块配置日志

#logger.conf

###############################################

[loggers]
keys=root,example01,example02

[logger_root]
level=DEBUG
handlers=hand01,hand02

[logger_example01]
handlers=hand01,hand02
qualname=example01
propagate=0

[logger_example02]
handlers=hand01,hand03
qualname=example02
propagate=0

###############################################

[handlers]
keys=hand01,hand02,hand03

[handler_hand01]
class=StreamHandler
level=INFO
formatter=form02
args=(sys.stderr,)

[handler_hand02]
class=FileHandler
level=DEBUG
formatter=form01
args=('myapp.log', 'a')

[handler_hand03]
class=handlers.RotatingFileHandler
level=INFO
formatter=form02
args=('myapp.log', 'a', 10*1024*1024, 5)

###############################################

[formatters]
keys=form01,form02

[formatter_form01]
format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s
datefmt=%a, %d %b %Y %H:%M:%S

[formatter_form02]
format=%(name)-12s: %(levelname)-8s %(message)s
datefmt=

上例3:

import logging
import logging.config

logging.config.fileConfig("logger.conf")
logger = logging.getLogger("example01")

logger.debug('This is debug message')
logger.info('This is info message')
logger.warning('This is warning message')

上例4:


import logging
import logging.config

logging.config.fileConfig("logger.conf")
logger = logging.getLogger("example02")

logger.debug('This is debug message')
logger.info('This is info message')
logger.warning('This is warning message')

3 通过JSON或者YAML文件配置logging模块

尽管可以在Python代码中配置logging,但是这样并不够灵活,最好的方法是使用一个配置文件来配置。在Python 2.7及以后的版本中,可以从字典中加载logging配置,也就意味着可以通过JSON或者YAML文件加载日志的配置。

3.1 通过JSON文件配置

JSON配置文件,

{
    "version":1,
    "disable_existing_loggers":false,
    "formatters":{
        "simple":{
            "format":"%(asctime)s - %(name)s - %(levelname)s - %(message)s"
        }
    },
    "handlers":{
        "console":{
            "class":"logging.StreamHandler",
            "level":"DEBUG",
            "formatter":"simple",
            "stream":"ext://sys.stdout"
        },
        "info_file_handler":{
            "class":"logging.handlers.RotatingFileHandler",
            "level":"INFO",
            "formatter":"simple",
            "filename":"info.log",
            "maxBytes":"10485760",
            "backupCount":20,
            "encoding":"utf8"
        },
        "error_file_handler":{
            "class":"logging.handlers.RotatingFileHandler",
            "level":"ERROR",
            "formatter":"simple",
            "filename":"errors.log",
            "maxBytes":10485760,
            "backupCount":20,
            "encoding":"utf8"
        }
    },
    "loggers":{
        "my_module":{
            "level":"ERROR",
            "handlers":["info_file_handler"],
            "propagate":"no"
        }
    },
    "root":{
        "level":"INFO",
        "handlers":["console","info_file_handler","error_file_handler"]
    }
}

通过JSON加载配置文件,然后通过logging.dictConfig配置logging,

import json
import logging.config
import os

def setup_logging(default_path = "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)

def func():
    logging.info("start func")

    logging.info("exec func")

    logging.info("end func")

if __name__ == "__main__":
    setup_logging(default_path = "logging.json")
    func()

3.2 通过YAML文件配置

通过YAML文件进行配置,比JSON看起来更加简介明了,

version: 1
disable_existing_loggers: False
formatters:
        simple:
            format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
handlers:
    console:
            class: logging.StreamHandler
            level: DEBUG
            formatter: simple
            stream: ext://sys.stdout
    info_file_handler:
            class: logging.handlers.RotatingFileHandler
            level: INFO
            formatter: simple
            filename: info.log
            maxBytes: 10485760
            backupCount: 20
            encoding: utf8
    error_file_handler:
            class: logging.handlers.RotatingFileHandler
            level: ERROR
            formatter: simple
            filename: errors.log
            maxBytes: 10485760
            backupCount: 20
            encoding: utf8
loggers:
    my_module:
            level: ERROR
            handlers: [info_file_handler]
            propagate: no
root:
    level: INFO
    handlers: [console,info_file_handler,error_file_handler]

通过YAML加载配置文件,然后通过logging.dictConfig配置logging,

import yaml
import logging.config
import os

def setup_logging(default_path = "logging.yaml",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 = yaml.load(f)
            logging.config.dictConfig(config)
    else:
        logging.basicConfig(level = default_level)

def func():
    logging.info("start func")

    logging.info("exec func")

    logging.info("end func")

if __name__ == "__main__":
    setup_logging(default_path = "logging.yaml")
    func()
    

4 Reference

每个 Python 程序员都要知道的日志实践

Python标准模块logging

python 的日志logging模块学习