Pulpcode

捕获，搅碎，拼接，吞咽

0%

如何打好一个日志

发表于 更新于 分类于 Valine：

我的工作，主要是在linux上写一些服务程序，而对于一个运行的服务来说，日志非常重要，因为它记录了运行时的所有信息。大多数情况下，我们很少去翻看自己的日志，但是如果系统出现异常，那么日志的作用就非常明显了。

而且不仅仅是在线上运行时，在调试程序的时候，打一些必要的debug级日志，对于定位错误也很有用，在上线的时候，我们只需要将日志级别设计为info，就可以“除去”这些debug信息了。

粗暴的过去

有那么一群粗暴的程序员，无论是调试代码，还是打印日志，总是会print各种上，首先这些print很少能留下极其有用的信息，还有你无法简单的将这些日志定位到各个地方（终端or文件），也不能已各种格式去打印它们，而且你还会将它们和真正的print进行混淆，很多人喜欢用print，仅仅是因为它们确实很简单，没什么门槛，所以同样的，它们什么也不能干。这些粗暴的人，永远都不会知道ipdb有多爽，logging有多爽。

python logging模块

每种语言都会带有logging模块，用法也是大同小异，绝对不会出现说我python能做的一个库，别的语言做不出来。

相比于print，日志有如下好处：

  1. 你可以控制消息的级别，过滤掉那些并不重要的消息。

  2. 你可决定输出到什么地方，以及怎么输出。

你可以打印不同级别的日志。

1
2
3
logger.debug('Debug...')
logger.info('Info...')
logger.error('Error...')

还可以设置打印的级别，比如如果你设置为info级别，就会过滤掉debug级别的日志。

1
logging.basicConfig(level=logging.Info)

还有日志的打印格式：

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

一般而言，都要为一个日志，设置多个handler，每个handler代表不同的行为，最常用的两种handler是StreamHandler和FileHandler,其中StreamHandler用来输出到流，而FileHandler用来输出到文件。

还有一种很常用的是TimeRotatingFileHandler,当日志文件较多，就可以使用此方法来按天切割，或者是按其他方式切割。

还可以使用配置文件，来配置各种参数，目前的python logger模块，不但支持fileConfg，和dictConfig的配置方式：

fileConfig:

1
2
3
4
5
6
7
8
9
[formatter_default]
format=%(asctime)s %(message)s
datefmt=%Y-%m-%d %H:%M:%S
class=logging.Formatter

[logger_mylogger]
level=DEBUG
handlers=console,file
propagate=1

dict:

1
2
3
4
5
6
7
8
9
'formatters': {
'verbose': {'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'},
'simple': {'format': '%(levelname)s %(message)s'},
'standard':{'format': '%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s'},
'default': {
'format' : '%(asctime)s %(message)s',
'datefmt' : '%Y-%m-%d %H:%M:%S'
}
},

还可以通过 json和yaml来记录日志。

这里要注意 disable_existing_loggers参数，防止在你加载配置之前就创建logger，然后发现没什么效果。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
{
    "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": ["console"],
            "propagate": "no"
        }
    }

}

载入json的代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
import json
import logging.config

def setup_logging(
    default_path='logging.json',
    default_level=logging.INFO,
    env_key='LOG_CFG'
):
    """Setup logging configuration

    """
    path = default_path
    value = os.getenv(env_key, None)
    if value:
        path = value
    if os.path.exists(path):
        with open(path, 'rt') as f:
            config = json.load(f)
        logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)

私房菜

在工作的过程中，总结了一些和打印日志有关的技巧，在这里分享一下。

调试代码

之前有说过，即使是调试代码，我也会使用日志模块而非print，[line:%(lineno)d]会显示行号，可以方便的让我知道，此条信息在那个位置。而且，这些地方，将来也可以直接作为真实的配置，改几行配置就ok了。

必要的打印

首先作为一个系统而言，大多数情况，你都要接受一些数据，处理它们，然后在返回一些数据给别人，（比如你的一个web server）。

所以接受到的数据，和你要发出去的数据，这些都是必须要打的。而且在和资源打交道的时候，也要记录关键的信息，那么哪些算是资源呢，就是你写try catch的地方，比如说磁盘访问，比如数据库访问，比如请求网络服务器，这些都算是与小系统的交互，必须要将输入和输出写入日志。而且这些内容都会伴有异常，所以遇到异常更是要已error写入logger。

作为一个webserver，我会将请求者的ip和请求时间，打印到日志中。

区分debug，info，error，critical

在调试的时候，一般使用debug,比如我在数据库操作时，会把将要执行的sql语句，做成debug。

1
logger.debug('sql ....' % (args..))

或者有大量中间状态的循环，我也会使用debug，来将结果打印。

日常处理就用info了，这算是使用最频率的打印了。

没有发生异常的错误，但是却是比较重要的事情，就应该使用warning：比如，当用户登录密码错误时，或者连接变慢时。

error经常就是和Exception搭配的东西了。

critical几乎没用过，据说磁盘满了，内存溢出，才会用到。

日志命名

很长一段时间，我在各种传日志对象，为了让它们公用一个日志文件，后面我使用了配置，而不是代码来设计日志的handler，在那些需要打印日志的模块中，它们只需要使用__name__获取就行了：

1
logger = logging.getLogger(__name__)

收集信息的技巧

需要注意的是，很多人在打印error的时候，直接error(e),实际上这样并不能记录完整的异常栈信息，你应该捕获异常并用 traceback 把它们记录下来。

1
2
except Exception as e:
    logger.error('Failed to Mysqldb', exc_info=True)

还有在打印类似于[],{},()等数据结构的时候，如果里面有中文，那么将打出来的是类似u'\u4f60\u597d'的unicode,这简直查看日志增加难度，一个比较好的做法，是把它们转成json再去打印，当然转也是有技巧的，需要设置参数。

1
json.dumps(d, ensure_ascii=False)

层次结构

日志消息类似事件，会在层次结构中流动

层次结构中的每个logger都有机会将这个消息输出、忽略、传递给父级。

而日志默认并没有配置其等级（或设置为NOTSET)）。这意味着logger只会把消息传递给父级，然后不断重复这个步骤，一直到根logger。（你设置等级，消息也是先处理，然后在传递给父类）

所以我们常常要配置根logger。使用basicConfig。因为无论怎样，所有的消息都会到root那里:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
# -*- coding: utf-8 -*-

import logging

logging.basicConfig(level=logging.DEBUG,
                format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s'
)

ff = logging.getLogger('foo')
ff.setLevel(logging.DEBUG)

console = logging.StreamHandler()
console.setLevel(logging.INFO)
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
console.setFormatter(formatter)

ff.addHandler(console)

ff.info("aiqier!")

找不到handler

初学python打日志的人，常常会看到一些：No handlers could be found for logger "xxx"

如果你没有配置任何日志处理函数，但是某处尝试打印日志消息。这个消息沿着层次结构向上传递，直到在结构链的顶处失败。所以要么你配置basicConfig，要么给你的logger加一个handler。