python模块之logging

一 日志记录的重要性

​ 在开发过程中，如果程序运行出现了问题，通常可以经过debug来检测到底是哪一步出现了问题，如果出现了问题的话，是比较容易排查出问题的。但是程序开发完成之后，部署到生产环境中去，这时候代码相当于是在一个黑盒环境下运行的，我们只能看到其运行的效果，是不能直接看到代码运行过程中的每一步状态的。在生产环境既不能通过debug来排查问题，更不能将生产环境下线来排查问题，所以这时候记录日志就很重要了。

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

​ 因此，作为开发者记录生产环境中代码运行的日志是很有必要的，因此学好怎么记录日志过程是一门必修课。

二 日志记录的流程框架

在python中，怎样才能算做一个比较标准的日志记录呢？像我之前都是使用控制台查看结果或者debug查看运行状态的，对于一个小项目来说，debug已经足够了，但是对于一个大项目来说一步一步调试费时费力，而且得到的消息也不一定全面，如果自己可以定义输出的调试信息那么对于调试来讲是件很节省时间的事。

在python中专门有一个用来记录日志的模块logging，可以用它来进行标注的日志记录，利用它我们可以更方便的进行日志记录，同时还可以做更方便的级别区分以及一些额外的日志信息的记录，如时间、运行模块信息等。

那么完整的日志记录流程框架是什么样呢？

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

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

这些就是整个logging模块的基本架构和对象功能。

三 日志记录的相关用法

logging模块有如下几个优点：

1. 可以在logging模块中设置日志等级，在不同的版本（如开发环境、生产环境）上通过设置不同的输出等级来记录相应的日志。
2. logging模块不仅可以把输出信息输出到控制台，还可以设置输出到任意位置，如写入文件、写入远程服务器等。
3. logging模块具有灵活的配置和格式化功能，如配置输出当前模块信息、运行时间等，相比print的字符串格式化更加方便易用。

四 日志记录的相关用法

一 日志级别

日志级别分为五个级别：

等级	数值
CRITICAL	50
FATAL	50
ERROR	40
WARNING	30
WARN	30
INFO	20
DEBUG	10
NOTSET	0

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

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

在logging模块中有对应的常量用来标识级别，默认情况下，默认的log级别是warning（30），默认输出到控制台。

二 自定义日志的配置

# test.py
import logging
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)
logger.info('log info')
logger.debug('log debug')
logger.warning('log warning')
logger.critical('log critical')

在这里首先导入logging模块，然后进行了一下基本的配置，通过basicConfig配置了level级别和format格式化信息，level配置为INFO级别，只输出大于等于INFO级别的信息，format格式的字符串，包括asctime、name、levelname、message四个内容，分别代表运行时间、模块名称、日志级别、日志内容，这样输出内容便为这四个内容的信息了，这就是logging全局配置。

接下来声明了一个Logger对象，是日志输出的主类，调用对象的info()方法可以输出INFO级别的日志信息，调用debug()方法就可以输出DEBUG级别的日志信息，其他级别的日志信息同理可以输出。初始化logger时传入了__name__来代替传入模块的名称，如果直接运行该脚本则值为__main__,如果作为模块被import的话，则就是被导入模块的名称为test.py，因为在不同的模块中该值不同，所以直接使用__name__代替，然后输出了四条日志信息，其中有一条INFO信息，一条DEBUG信息，一条WARNING信息，一条CRITICAL信息，因为设置的level为INFO，所以低于INFO的级别日志会被过滤，所以DEBUG日志信息会被过滤。

三 basicConfig的具体参数

basicConfig是用作全局的日志配置，basicConfig的参数有：

1. filename：日志输出的文件名，如果指定了这个信息之后，不会使用默认的StreamHandler，会使用FileHandler来将日志信息输入到指定的文件中。

2. filemode：该参数为指定日志文件的写入方式，有两种形式，一种为w，一种为a，分别代表覆盖写入和追加写入。

3. format：指定日志信息的输出格式，即上文示例所示的参数，部分参数如下：

   1. %(levelno)s：打印日志级别的值；
   2. %(levelname)s：打印日志级别的名称；
   3. %(pathname)s：打印当前执行程序的路径，其实就是sys.argv[0]；
   4. %(filenam)s：打印当前执行程序名；
   5. %(funcName)s：打印日志的当前函数；
   6. %(lineno)s：打印日志的当前行号；
   7. %(asctime)s：打印日志的时间；
   8. %(thread)s：打印线程id；
   9. %(threadName)s：打印线程名称；
   10. %(process)s：打印进程id；
   11. %(processName)s：打印进程名称；
   12. %(module)s：打印模块名称；
   13. %(message)s：打印日志信息。

4. datefmt：指定时间的输出格式。

5. style：如果format参数制定了，这个参数就可以指定格式化时的占位符风格，如%、{、$等。

6. level：指定日志输出的类别，程序会输出大于等于此级别的信息。

7. stream：在没有指定filename的时候会默认使用StreamHandler，这时stream可以指定初始化的文件流。

8. handlers：可以指定日志处理时所使用的Handlers，必须是可迭代的。

四 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('debug')
logger.critical('critical')
logger.error('error')
logger.warning('warning')
logger.info('info')

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

2018/10/20 00:26:25 - __main__ - CRITICAL - critical
2018/10/20 00:26:25 - __main__ - ERROR - error
2018/10/20 00:26:25 - __main__ - WARNING - warning

这样可以为每个Handler单独配置输出的格式。

五 捕获Tracback异常信息

遇到错误的时候，希望报错时出现详细的Tracback信息，便于我们调试，利用logging模块可以非常方便的实现这种需求。

import logging

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

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

file_handler = logging.FileHandler('test.log')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

stream_handler = logging.StreamHandler()
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

logger.info('INFO')
logger.warning('WARNING')
try:
    num = 1/0
except Exception:
    logger.error('something wrong', exc_info=True)
    
logger.info('end')

这里在error()方法中添加了一个参数，将exc_info设置为True，这样就可以输出执行过程中的信息了，即可以输出完整的Tracback信息。

运行结果如下：

2018-10-20 00:36:38,007 - __main__ - INFO - INFO
2018-10-20 00:36:38,007 - __main__ - WARNING - WARNING
2018-10-20 00:36:38,007 - __main__ - ERROR - something wrong
Traceback (most recent call last):
  File "/Users/jingxing/PycharmProjects/python全栈/day22/log_test.py", line 58, in <module>
    num = 1 / 0
ZeroDivisionError: division by zero
2018-10-20 00:36:38,007 - __main__ - INFO - end

这样可以详细的记录报错的信息，一旦出现了错误，可以及时的定位到出现问题的代码。

六 配置共享

在写项目的时候，肯定会有许多的配置信息，如果每个文件都来配置logging的话非常麻烦，而且几乎很多地方的配置几乎差不多的，因为此原因，logging模块提供了父子模块共享配置的机制，会根据Logger的名称来自动加载父模块的配置。

定义一个main.py文件：

# main.py
import logging
import core

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

handler = logging.FileHandler('test.log')
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - % (message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logging.info('main info')
logging.debug('main debug')
logging.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')

在core.py文件里定义了Logger的名称为main.core，因为之前在main.py文件里定义的Logger名称为main，所以core.py里面的Logger就会复用main.py里面的Logger配置，而不用重新为core配置日志了。

运行之后test.log结果如下：

2018-10-20 10:15:37,575 - main - INFO 
2018-10-20 10:15:37,575 - main - DEBUG 
2018-10-20 10:15:37,575 - main - ERROR 
2018-10-20 10:15:37,575 - main.core - INFO 
2018-10-20 10:15:37,575 - main.core - DEBUG 
2018-10-20 10:15:37,575 - main.core - ERROR 

可以看出main和core模块都是用了同样的输出配置。所以只要在入口文件里定义好logging模块的输出配置，子模块只需要在定义Logger对象时使用父模块的名称开头就可以共享配置，实际上直接使用父模块的名字就可以，但是为了增加辨识度，可以在父模块名字后加上后缀。

查看getLogger源码可得，后面的名字可以自定义，然后getLogger里面会自动帮你创建以该名字命名的日志生成器，具体解释如下：

获取具有指定名称（通道名称）的记录器，如果它尚不存在则创建它。 此名称是以点分隔的分层名称，例如“a”，“a.b”，“a.b.c”或类似名称。如果指定名称存在PlaceHolder [即 loggerdid不存在，但它的子节点已经存在]，用createdlogger替换它，并修复指向占位符的父/子引用，现在指向记录器。

七 文件配置

虽然可以再入口文件中定义好配置信息，然后子模块也可以使用很方便，但是因为配置文件大部分都是不需要更改的，只是某些需要更改，像这种信息可以把配置写入配置文件里，然后运行时读取配置文件里面的配置，这样更易维护和使用。

项目结构如下：

# bin/start.py
import os,sys
sys.path.append(os.path.dirname(os.path.dirname(__file__)))
import core.shop
def run():
    print("welcome to here")
    core.shop.shopping()

run()

# conf/settings
standard_format = "%(name)s %(asctime)s %(levelname)s %(module)s %(funcName)s %(lineno)s %(message)s"
simple_format = "%(name)s %(asctime)s  %(module)s  %(message)s"
complete_format = "%(asctime)s %(levelname)s %(funcName)s %(lineno)s %(thread)s %(process)s %(message)s"
logfile_path = r"/Users/jingxing/PycharmProjects/python全栈/day23/log/d.log"

LOGGING_DIC = {
    'version': 1,
    'formatters': {
        'standard': {
            'format': standard_format
        },
        'simple': {
            'format': simple_format
        },
        "complete":{
            "format": complete_format
        }
    },
    'filters': {},
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'default': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'formatter': 'standard',
            'filename': logfile_path,  #
            'maxBytes': 1024 * 1024 * 5,  # 日志文件的最大大小为5M 超出后 换文件
            'backupCount': 5, # 最多留五个日志文件
            'encoding': 'utf-8',
        },
    },
    'loggers': {
        # 在getLogger的时候  如果指定的名称 不存在 或者不给名称 用的就是默认的
        # 在这里如果key为空 它就是默认的
        # 你可以自己定义生成器的名称 并且他们还能使用相同的默认配置
        '': {
            'handlers': ['default', 'console'],
            'level': 'DEBUG',
            'propagate': False,
        },
    },
}

# core/shop.py
import lib.common
logger = lib.common.get_logger()

def shopping():
    print("开始购物")
    logger.debug("购物成功")

# lib/common.py
import conf.settings
import logging.config

def get_logger():
    logging.config.dictConfig(conf.settings.LOGGING_DIC)
    return logging.getLogger("main")

在代码运行后，在shop.py模块中导入了lib.common模块，在common.py模块中导入了conf.settings模块，来获取具体的日志配置，因为getLogger('main')里面的main在settings里面没有，所以使用默认的日志配置，如下：

'loggers': {
        # 在getLogger的时候  如果指定的名称 不存在 或者不给名称 用的就是默认的
        # 在这里如果key为空 它就是默认的
        # 你可以自己定义生成器的名称 并且他们还能使用相同的默认配置
        '': {
            'handlers': ['default', 'console'],
            'level': 'DEBUG',
            'propagate': False,
        }

然后首先进行level='DEBUG'的过滤，因为shopping中的日志信息级别为debug，所以会通过进入handlers里面进行第二次过滤，在handlers里面有两个配置，一个为default配置，一个味console配置，在default配置中，具体配置如下：

'default': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'formatter': 'standard',
            'filename': logfile_path,  #
            'maxBytes': 1024 * 1024 * 5,  # 日志文件的最大大小为5M 超出后 换文件
            'backupCount': 5, # 最多留五个日志文件
            'encoding': 'utf-8',
        }

发现日志级别为DEBUG，所以仍然不会过滤，接下来就是格式化输出到指定文件了，formatter为standard模式，filename之前都已经定义好了，同理console同理输出到控制台。